Something has to be updating one of the tables or you couldn't get ORA-01555. I would check to see if any of the code is doing 'select for update' rather than a simple 'update'. There are versions of Oracle where 'select for update' can result in large numbers of CR copies of blocks and produces the symptoms you've described. Another possibility is that there is something about the data and index on T3 with it "less than" clause which results in identical access paths, but extremely different amounts of work being done as the data changes over discrete time intervals. The execution path, index definitions, and column types might give a clue. Regards Jonathan Lewis http://www.jlcomp.demon.co.uk The Co-operative Oracle Users' FAQ http://www.jlcomp.demon.co.uk/faq/ind_faq.html Optimising Oracle Seminar http://www.jlcomp.demon.co.uk/seminar.html June 2004 UK Manchester July 2004 Iceland July 2004 USA California Aug 2004 USA North Carolina Sept 2004 UK Manchester Sept 2004 USA NYC Oct 2004 USA Boston ----- Original Message ----- From: "Daniel Fink" <Daniel.Fink@xxxxxxx> To: <oracle-l@xxxxxxxxxxxxx> Sent: Monday, May 03, 2004 9:05 PM Subject: A Tale of Two SQLs It was the best of sql executions; it was the worst of sql executions. We have a process that periodically slows down. So far, we have not been able to pinpoint a root cause, but we continue to pester the development/application support folks for more info. I apologize for the limited information, but I'm hoping that we are aiming in the right direction. We are smart enough that we captured a 10046 trace during a good execution as a baseline. I have tagged the lines from this trace file as (good). This morning, the query began slowing down (eventually it will get a 1555 error). We turned on tracing and those lines are tagged as (bad). To make sure I am comparing apples to apples, the statements are identical, even the bind variables are identical. I'm not going to post the 2 trace files (almost 500m), so I'm including the relevant parts. There are no waits in these execution/fetches (you read it correctly, no db file waits, no sql*net waits). I've also changed the statments to remove any table/column names. What I have found is that the first FETCH of the bad execution is significantly (300 - 700x) slower than the good execution. It also performs significantly more (500x) consistent reads. Subsequent FETCHes are nearly identical to each other (in terms of good = bad). These FETCHes are performed tens of thousands of times as this query is re-executed with different bind variables (also note the time difference in the EXECs, but it pales in comparison). My theory is that the high number of crs in the first FETCH of each execution are the result of building a read-consistent version of the data. Again, we are working with the dev/app folks to confirm that one of these tables is being modified, but have not had a response yet. Comments on my theory? 'Tis a far, far better thing I do... Daniel Bad SQL ===================== PARSING IN CURSOR #10(bad) len=295 dep=1 uid=86 oct=3 lid=86 tim=746385804887 hv=3414111617 ad='93b1bcf0' SELECT t1.col1 from table1 t1, table2 t2 where t2.col2 = :b1 and t2.col2 = t1.col2 union select max(t3.col3) from table3 t3 where t3.col4 = substr(:b1, 1, 6) and t3.col3 < :b1 END OF STMT Good SQL ===================== PARSING IN CURSOR #7(good) len=295 dep=1 uid=63 oct=3 lid=63 tim=26349629222266 hv=3414111617 ad='8c9aee70' SELECT t1.col1 from table1 t1, table2 t2 where t2.col2 = :b1 and t2.col2 = t1.col2 union select max(t3.col3) from table3 t3 where t3.col4 = substr(:b1, 1, 6) and t3.col3 < :b1 END OF STMT EXEC #10(bad):c=0,e=701,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=746385804872 EXEC #7(good):c=0,e=536,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=26349629222259 FETCH #10(bad):c=110000,e=107303,p=0,cr=7699,cu=0,mis=0,r=1,dep=1,og=4,tim=7463859 12781 FETCH #7(good):c=0,e=406,p=0,cr=16,cu=0,mis=0,r=1,dep=1,og=4,tim=26349629222976 FETCH #10(bad):c=0,e=30,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=746385913106 FETCH #7(good):c=0,e=31,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=26349629223153 BINDS #10(bad): bind 0: dty=1 mxl=32(09) mal=00 scl=00 pre=00 oacflg=13 oacfl2=1 size=96 offset=0 bfp=ffffffff7c4b7c38 bln=32 avl=09 flg=05 value="104539-08" bind 1: dty=1 mxl=32(09) mal=00 scl=00 pre=00 oacflg=13 oacfl2=1 size=0 offset=32 bfp=ffffffff7c4b7c58 bln=32 avl=09 flg=01 value="104539-08" bind 2: dty=1 mxl=32(09) mal=00 scl=00 pre=00 oacflg=13 oacfl2=1 size=0 offset=64 bfp=ffffffff7c4b7c78 bln=32 avl=09 flg=01 value="104539-08" BINDS #7(good): bind 0: dty=1 mxl=32(09) mal=00 scl=00 pre=00 oacflg=13 oacfl2=1 size=96 offset=0 bfp=ffffffff7c4aeac0 bln=32 avl=09 flg=05 value="104539-08" bind 1: dty=1 mxl=32(09) mal=00 scl=00 pre=00 oacflg=13 oacfl2=1 size=0 offset=32 bfp=ffffffff7c4aeae0 bln=32 avl=09 flg=01 value="104539-08" bind 2: dty=1 mxl=32(09) mal=00 scl=00 pre=00 oacflg=13 oacfl2=1 size=0 offset=64 bfp=ffffffff7c4aeb00 bln=32 avl=09 flg=01 value="104539-08" EXEC #10(bad):c=0,e=619,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=746385914651 EXEC #7(good):c=0,e=496,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=26349629224220 FETCH #10(bad):c=110000,e=102469,p=0,cr=7698,cu=0,mis=0,r=1,dep=1,og=4,tim=7463860 17309 FETCH #7(good):c=0,e=206,p=0,cr=16,cu=0,mis=0,r=1,dep=1,og=4,tim=26349629224499 FETCH #10(bad):c=0,e=12,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=746386017582 FETCH #7(good):c=0,e=6,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=26349629224619 FETCH #10(bad):c=0,e=8,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=746386017774 FETCH #7(good):c=0,e=5,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=26349629224734 FETCH #10(bad):c=0,e=9,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=746386017967 FETCH #7(good):c=0,e=5,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=26349629224849 FETCH #10(bad):c=0,e=8,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=746386018157 FETCH #7(good):c=0,e=5,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=26349629224961 FETCH #10(bad):c=0,e=26,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=746386018363 FETCH #7(good):c=0,e=14,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=26349629225081 BINDS #10(bad): bind 0: dty=1 mxl=32(09) mal=00 scl=00 pre=00 oacflg=13 oacfl2=1 size=96 offset=0 bfp=ffffffff7c4b7c38 bln=32 avl=09 flg=05 value="104539-07" bind 1: dty=1 mxl=32(09) mal=00 scl=00 pre=00 oacflg=13 oacfl2=1 size=0 offset=32 bfp=ffffffff7c4b7c58 bln=32 avl=09 flg=01 value="104539-07" bind 2: dty=1 mxl=32(09) mal=00 scl=00 pre=00 oacflg=13 oacfl2=1 size=0 offset=64 bfp=ffffffff7c4b7c78 bln=32 avl=09 flg=01 value="104539-07" BINDS #7(good): bind 0: dty=1 mxl=32(09) mal=00 scl=00 pre=00 oacflg=13 oacfl2=1 size=96 offset=0 bfp=ffffffff7c4aeac0 bln=32 avl=09 flg=05 value="104539-07" bind 1: dty=1 mxl=32(09) mal=00 scl=00 pre=00 oacflg=13 oacfl2=1 size=0 offset=32 bfp=ffffffff7c4aeae0 bln=32 avl=09 flg=01 value="104539-07" bind 2: dty=1 mxl=32(09) mal=00 scl=00 pre=00 oacflg=13 oacfl2=1 size=0 offset=64 bfp=ffffffff7c4aeb00 bln=32 avl=09 flg=01 value="104539-07" EXEC #10(bad):c=0,e=684,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=746386019967 EXEC #7(good):c=0,e=463,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=26349629226116 FETCH #10(bad):c=100000,e=101693,p=0,cr=7697,cu=0,mis=0,r=1,dep=1,og=4,tim=7463861 21784 FETCH #7(good):c=0,e=186,p=0,cr=16,cu=0,mis=0,r=1,dep=1,og=4,tim=26349629226374 FETCH #10(bad):c=0,e=12,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=746386122056 FETCH #7(good):c=0,e=6,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=26349629226492 FETCH #10(bad):c=0,e=26,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=746386122263 FETCH #7(good):c=0,e=14,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=26349629226615 BINDS #10(bad): bind 0: dty=1 mxl=32(09) mal=00 scl=00 pre=00 oacflg=13 oacfl2=1 size=96 offset=0 bfp=ffffffff7c4b7c38 bln=32 avl=09 flg=05 value="107278-01" bind 1: dty=1 mxl=32(09) mal=00 scl=00 pre=00 oacflg=13 oacfl2=1 size=0 offset=32 bfp=ffffffff7c4b7c58 bln=32 avl=09 flg=01 value="107278-01" bind 2: dty=1 mxl=32(09) mal=00 scl=00 pre=00 oacflg=13 oacfl2=1 size=0 offset=64 bfp=ffffffff7c4b7c78 bln=32 avl=09 flg=01 value="107278-01" BINDS #7(good): bind 0: dty=1 mxl=32(09) mal=00 scl=00 pre=00 oacflg=13 oacfl2=1 size=96 offset=0 bfp=ffffffff7c4aeac0 bln=32 avl=09 flg=05 value="107278-01" bind 1: dty=1 mxl=32(09) mal=00 scl=00 pre=00 oacflg=13 oacfl2=1 size=0 offset=32 bfp=ffffffff7c4aeae0 bln=32 avl=09 flg=01 value="107278-01" bind 2: dty=1 mxl=32(09) mal=00 scl=00 pre=00 oacflg=13 oacfl2=1 size=0 offset=64 bfp=ffffffff7c4aeb00 bln=32 avl=09 flg=01 value="107278-01" EXEC #10(bad):c=0,e=686,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=746386123823 EXEC #7(good):c=0,e=466,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=26349629227628 FETCH #10(bad):c=200000,e=204295,p=0,cr=15358,cu=0,mis=0,r=1,dep=1,og=4,tim=746386 328243 FETCH #7(good):c=0,e=143,p=0,cr=7,cu=0,mis=0,r=1,dep=1,og=4,tim=26349629227843 FETCH #10(bad):c=0,e=37,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=746386328513 FETCH #7(good):c=0,e=13,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=26349629227941 BINDS #10(bad): bind 0: dty=1 mxl=32(09) mal=00 scl=00 pre=00 oacflg=13 oacfl2=1 size=96 offset=0 bfp=ffffffff7c4b7c38 bln=32 avl=09 flg=05 value="107366-01" bind 1: dty=1 mxl=32(09) mal=00 scl=00 pre=00 oacflg=13 oacfl2=1 size=0 offset=32 bfp=ffffffff7c4b7c58 bln=32 avl=09 flg=01 value="107366-01" bind 2: dty=1 mxl=32(09) mal=00 scl=00 pre=00 oacflg=13 oacfl2=1 size=0 offset=64 bfp=ffffffff7c4b7c78 bln=32 avl=09 flg=01 value="107366-01" BINDS #7(good): bind 0: dty=1 mxl=32(09) mal=00 scl=00 pre=00 oacflg=13 oacfl2=1 size=96 offset=0 bfp=ffffffff7c4aeac0 bln=32 avl=09 flg=05 value="107366-01" bind 1: dty=1 mxl=32(09) mal=00 scl=00 pre=00 oacflg=13 oacfl2=1 size=0 offset=32 bfp=ffffffff7c4aeae0 bln=32 avl=09 flg=01 value="107366-01" bind 2: dty=1 mxl=32(09) mal=00 scl=00 pre=00 oacflg=13 oacfl2=1 size=0 offset=64 bfp=ffffffff7c4aeb00 bln=32 avl=09 flg=01 value="107366-01" EXEC #10(bad):c=0,e=706,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=746386330128 EXEC #7(good):c=10000,e=493,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=26349629228936 FETCH #10(bad):c=210000,e=208902,p=0,cr=15673,cu=0,mis=0,r=1,dep=1,og=4,tim=746386 539152 FETCH #7(good):c=0,e=121,p=0,cr=7,cu=0,mis=0,r=1,dep=1,og=4,tim=26349629229130 FETCH #10(bad):c=0,e=35,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=746386539431 FETCH #7(good):c=0,e=12,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=26349629229225 ---------------------------------------------------------------- Please see the official ORACLE-L FAQ: http://www.orafaq.com ---------------------------------------------------------------- To unsubscribe send email to: oracle-l-request@xxxxxxxxxxxxx put 'unsubscribe' in the subject line. -- Archives are at //www.freelists.org/archives/oracle-l/ FAQ is at //www.freelists.org/help/fom-serve/cache/1.html ----------------------------------------------------------------- ---------------------------------------------------------------- Please see the official ORACLE-L FAQ: http://www.orafaq.com ---------------------------------------------------------------- To unsubscribe send email to: oracle-l-request@xxxxxxxxxxxxx put 'unsubscribe' in the subject line. -- Archives are at //www.freelists.org/archives/oracle-l/ FAQ is at //www.freelists.org/help/fom-serve/cache/1.html -----------------------------------------------------------------