| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
 |
 | |||
| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
|
| |||
Home -> Community -> Mailing Lists -> Oracle-L -> RE: 10046 Trace question
Raj,
Nothing unusual about this that I can see...
You've done three single-block reads (p3=3D1) in the context of a fetch c=
all.
You can see the p=3D3 right in the FETCH line.
There's a date stamp preceding the FETCH line. Oracle emits one of these (KSDDDT) prior to any line of trace file output that is printed more than=
10=A0seconds after the time of the prior write to trace. The FETCH took a=
long
time because it visited the buffer cache a LOT of times, cr+cu=3D817,052+=
0 to
be exact.
All this forms a common pattern associated with an inefficient execution plan, which is undoubtedly wasting tons of CPU time on your system (114=A0seconds on this execution alone).
<grin>But on the bright side, your database buffer cache hit ratio for th=
is
SQL statement is absolutely spectacular.</grin>
Cary Millsap
Hotsos Enterprises, Ltd.
http://www.hotsos.com
* Nullius in verba *
Visit www.hotsos.com for curriculum and schedule details...
-----Original Message-----
From: oracle-l-bounce_at_freelists.org [mailto:oracle-l-bounce_at_freelists.org=
]
On Behalf Of rjamya
Sent: Tuesday, April 26, 2005 12:32 PM
To: Oracle Discussion List
Subject: 10046 Trace question
Hi all,
I am testing performance of a query that produced some interesting output=
s=20
in the raw trace file. I cannot explain this, can someone?
Raj
PARSING IN CURSOR #1 len=3D1540 dep=3D0 uid=3D44 oct=3D3 lid=3D44 tim=3D1= 088413968080921
hv=3D3734675936 ad=3D'27ee5260'=20
SELECT distinct pscp_pa_id, pr_brnd_id, brnd_name, pa_agnc_id, pa_advr_id=
,=20
=2E...
END OF STMT=20
PARSE
#1:c=3D50000,e=3D62605,p=3D0,cr=3D109,cu=3D0,mis=3D1,r=3D0,dep=3D0,og=3D0=
,tim=3D1088413968080915
EXEC #1:c=3D0,e=3D655,p=3D0,cr=3D0,cu=3D0,mis=3D0,r=3D0,dep=3D0,og=3D4,ti=
m=3D1088413968171161=20
WAIT #1: nam=3D'SQL*Net message to client' ela=3D 23 p1=3D1650815232 p2=3D=
1 p3=3D0=20
WAIT #1: nam=3D'global cache cr request' ela=3D 528 p1=3D32 p2=3D93812=20
p3=3D504403158399474816=20
WAIT #1: nam=3D'db file sequential read' ela=3D 460 p1=3D32 p2=3D93812 p3=
=3D1=20
WAIT #1: nam=3D'global cache cr request' ela=3D 446 p1=3D32 p2=3D93832=20
p3=3D504403158349232736=20
WAIT #1: nam=3D'db file sequential read' ela=3D 396 p1=3D32 p2=3D93832 p3=
=3D1=20
WAIT #1: nam=3D'db file sequential read' ela=3D 385 p1=3D31 p2=3D55448 p3=
=3D1=20
*** 2005-04-26 13:20:17.483=20
FETCH
#1:c=3D114080000,e=3D111402747,p=3D3,cr=3D817052,cu=3D0,mis=3D0,r=3D1,dep=
=3D0,og=3D4,tim=3D10884
14079574042
WAIT #1: nam=3D'SQL*Net message from client' ela=3D 1012 p1=3D1650815232 p= 2=3D1 p3=3D0
FETCH #1:c=3D0,e=3D28,p=3D0,cr=3D0,cu=3D0,mis=3D0,r=3D0,dep=3D0,og=3D4,ti=
m=3D1088414079575522=20
WAIT #1: nam=3D'SQL*Net message to client' ela=3D 2 p1=3D1650815232 p2=3D=
1 p3=3D0=20
WAIT #1: nam=3D'SQL*Net message from client' ela=3D 1137 p1=3D1650815232 p=
2=3D1 p3=3D0
XCTEND rlbk=3D0, rd_only=3D1=20
See the FETCH line, before that there are 3 'db file sequential reads' bu=
t=20
FETCH line reports 817052 cr reads. It seems we are missing whle lot of=20
trace lines, but trust me, this is what I have. They query appears to han=
g,=20
and then comes back. The difference between tim for PARSE and FETCH agree=
s=20
with e=3D value on the FETCH line.=20
Am I interpreting this wrong? or should i expect to see many more lines i=
n=20
here for cr reads? The trace is enabled by alter session 10046^12. I have=
=20
trimmed the sqltext and binds information for obvious information.
Any ideas? This is 9204 btw.
Raj
-- http://www.freelists.org/webpage/oracle-l -- http://www.freelists.org/webpage/oracle-lReceived on Tue Apr 26 2005 - 13:48:11 CDT
 |
 |