Re: Trace file Anomolies

From: Jonathan Lewis <jonathan_at_jlcomp.demon.co.uk>
Date: Thu, 11 Nov 2004 10:47:08 +0000 (UTC)
Message-ID: <cmvfvb$bub$1@hercules.btinternet.com>

Normally, you would expect to see STAT lines only when cursors close. However, I have recently started to find trace files which fail to dump STAT lines in circumstances when I know they should have.

At present I have only seen this in 9.2.0.4, but I haven't tried to make it happen in other versions, and haven't investigated possible causes.

Do you have a session cursor cache defined ? It shouldn't have this effect, but maybe there's a side effect from some recent tweaking.

I notice, also, that your trace file shows you are parsing statements twice. This is probably a hidden feature of your development environment - but possibly it is hitting a code error in Oracle that 'gets confused' about whether the cursor has closed or not.

You could check to see if there is any correlation between double-parses and failing to dump STAT lines.

-- 
Regards

Jonathan Lewis

http://www.jlcomp.demon.co.uk/faq/ind_faq.html
The Co-operative Oracle Users' FAQ

http://www.jlcomp.demon.co.uk/seminar.html
Optimising Oracle Seminar - schedule updated Sept 19th





"Matt" <mccmx_at_hotmail.com> wrote in message 
news:cfee5bcf.0411100613.71f4c281_at_posting.google.com...


> Oracle 9.2.0.4 EE Windows 2K

>

> Why is it that some SQL statements produce STAT lines in the trace

> output but others don't..?

>

> e.g.: Some of the statements below produce STAT lines but others

> don't.

>

> When I format the trace file with tkprof I am missing the "Row source

> operation" plans for some statements....

>

> =====================

> PARSING IN CURSOR #25 len=117 dep=0 uid=21 oct=3 lid=21 tim=1019579390

> hv=2091399012 ad='68fcec7c'

> SELECT X0.DATETIME_STAMP  from  PS_HRMSSI_AUDIT X0 where

> X0.AUDITRECNAME = 'AUD_PERS_DTAEFF' and   X0.HRMSSI_ID = :1

> END OF STMT

> PARSE #25:c=0,e=61,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1019579384

> =====================

> PARSING IN CURSOR #25 len=117 dep=0 uid=21 oct=3 lid=21 tim=1019579974

> hv=2091399012 ad='68fcec7c'

> SELECT X0.DATETIME_STAMP  from  PS_HRMSSI_AUDIT X0 where

> X0.AUDITRECNAME = 'AUD_PERS_DTAEFF' and   X0.HRMSSI_ID = :1

> END OF STMT

> PARSE #25:c=0,e=37,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1019579967

> EXEC #25:c=0,e=42,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1019580139

> FETCH #25:c=0,e=41,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=4,tim=1019580224

> FETCH #25:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1019580653

> STAT #8 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=151 r=0

> w=0 time=35883 us)'

> STAT #8 id=2 cnt=15815 pid=1 pos=1 obj=7744 op='TABLE ACCESS FULL

> PS_AUD_PERSON (cr=151 r=0 w=0 time=17564 us)'

> =====================

> PARSING IN CURSOR #8 len=64 dep=0 uid=21 oct=3 lid=21 tim=1019582279

> hv=1190273382 ad='69587f0c'

> SELECT sysdate, max(X1.AUDIT_STAMP)  from PS_AUD_PERS_DTAEFF X1

> END OF STMT

> PARSE #8:c=0,e=55,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1019582273

> =====================

> PARSING IN CURSOR #8 len=64 dep=0 uid=21 oct=3 lid=21 tim=1019582894

> hv=1190273382 ad='69587f0c'

> SELECT sysdate, max(X1.AUDIT_STAMP)  from PS_AUD_PERS_DTAEFF X1

> END OF STMT

> PARSE #8:c=0,e=38,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1019582888

> EXEC #8:c=0,e=62,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1019583055

> FETCH 

> #8:c=46875,e=44751,p=0,cr=539,cu=0,mis=0,r=1,dep=0,og=4,tim=1019627849

> FETCH #8:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1019628597

> STAT #24 id=1 cnt=0 pid=0 pos=1 obj=0 op='SORT UNIQUE (cr=183 r=0 w=0

> time=5176 us)'

> STAT #24 id=2 cnt=0 pid=1 pos=1 obj=0 op='NESTED LOOPS  (cr=183 r=0

> w=0 time=5140 us)'

> STAT #24 id=3 cnt=0 pid=2 pos=1 obj=0 op='NESTED LOOPS  (cr=183 r=0

> w=0 time=5137 us)'

> STAT #24 id=4 cnt=4 pid=3 pos=1 obj=0 op='NESTED LOOPS  (cr=181 r=0

> w=0 time=5102 us)'

> STAT #24 id=5 cnt=4 pid=4 pos=1 obj=7744 op='TABLE ACCESS FULL

> PS_AUD_PERSON (cr=151 r=0 w=0 time=4671 us)'

> STAT #24 id=6 cnt=4 pid=4 pos=2 obj=17903 op='TABLE ACCESS BY INDEX

> ROWID PS_JOB (cr=30 r=0 w=0 time=382 us)'

> STAT #24 id=7 cnt=4 pid=6 pos=1 obj=17910 op='INDEX RANGE SCAN PSAJOB

> (cr=26 r=0 w=0 time=341 us)'

> STAT #24 id=8 cnt=3 pid=7 pos=2 obj=0 op='SORT AGGREGATE (cr=8 r=0 w=0

> time=64 us)'

> STAT #24 id=9 cnt=3 pid=8 pos=1 obj=0 op='FIRST ROW  (cr=8 r=0 w=0

> time=44 us)'

> STAT #24 id=10 cnt=3 pid=9 pos=1 obj=17910 op='INDEX RANGE SCAN

> (MIN/MAX) PSAJOB (cr=8 r=0 w=0 time=34 us)'

> STAT #24 id=11 cnt=3 pid=7 pos=2 obj=0 op='SORT AGGREGATE (cr=8 r=0

> w=0 time=57 us)'

> STAT #24 id=12 cnt=3 pid=11 pos=1 obj=0 op='FIRST ROW  (cr=8 r=0 w=0

> time=41 us)'

> STAT #24 id=13 cnt=3 pid=12 pos=1 obj=17910 op='INDEX RANGE SCAN

> (MIN/MAX) PSAJOB (cr=8 r=0 w=0 time=33 us)'

> STAT #24 id=14 cnt=0 pid=3 pos=2 obj=17185 op='INDEX UNIQUE SCAN

> PS_HRMSSI_COMPANY (cr=2 r=0 w=0 time=18 us)'

> STAT #24 id=15 cnt=0 pid=2 pos=2 obj=19671 op='TABLE ACCESS BY INDEX

> ROWID PS_PERSON (cr=0 r=0 w=0 time=0 us)'

> STAT #24 id=16 cnt=0 pid=15 pos=1 obj=19672 op='INDEX UNIQUE SCAN

> PS_PERSON (cr=0 r=0 w=0 time=0 us)'

> =====================

Received on Thu Nov 11 2004 - 04:47:08 CST