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: <k.sriramkumar_at_iflexsolutions.com>
Date: Tue, 4 May 2004 14:16:21 +0530
Message-ID: <10898BE7CA96D611988B000802255AAF03427DF2@FMGRT.rt.i-flex.com> 





Hi Daniel,
 


Looking at the statements 
 


PARSING IN CURSOR #10(bad) len=295 dep=1 uid=86 oct=3 lid=86 and PARSING IN CURSOR #7(good) len=295 dep=1 uid=63 oct=3 lid=63



They are being owned and parsed by diffrent id's(63 for bad and 86 for good).  Are they refering to diffrent objects by any chance?



Best Regards



Sriram Kumar

 


 


	-----Original Message----- 
	From: oracle-l-bounce_at_freelists.org on behalf of Daniel Fink 
	Sent: Tue 5/4/2004 1:35 AM 
	To: oracle-l_at_freelists.org 
	Cc: 
	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=746385912781

	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=746386017309

	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=746386121784

	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=746386328243

	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=746386539152

	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
	-----------------------------------------------------------------
	

-- Binary/unsupported file stripped by Ecartis --


-- Type: application/ms-tnef


-- File: winmail.dat






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 Tue May 04 2004 - 03:39:50 CDT












Original text of this message













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