Oracle FAQ Your Portal to the Oracle Knowledge Grid
HOME | ASK QUESTION | ADD INFO | SEARCH | E-MAIL US
 

Home -> Community -> Mailing Lists -> Oracle-L -> Re: A Tale of Two SQLs

Re: A Tale of Two SQLs

From: Jonathan Lewis <jonathan_at_jlcomp.demon.co.uk>
Date: Mon, 3 May 2004 21:45:15 +0100
Message-ID: <008c01c4314f$8a88b910$7102a8c0@Primary> 






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







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_at_freelists.org
put 'unsubscribe' in the subject line.

--
Archives are at http://www.freelists.org/archives/oracle-l/
FAQ is at http://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_at_freelists.org
put 'unsubscribe' in the subject line.
--
Archives are at http://www.freelists.org/archives/oracle-l/
FAQ is at http://www.freelists.org/help/fom-serve/cache/1.html
-----------------------------------------------------------------


Received on Mon May 03 2004 - 15:42:59 CDT












Original text of this message













  HOME |
  ASK QUESTION |
  ADD INFO |
  SEARCH |
  E-MAIL US