Re: Trace file Anomolies

"Jonathan Lewis" <jonathan_at_jlcomp.demon.co.uk> wrote in message news:<cmvfvb$bub$1_at_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.

Try this on 9.2.0.5:

dellera_at_ORACLE9I> alter session set tracefile_identifier='YYY';

Session altered.

dellera_at_ORACLE9I> alter session set events '10046 trace name context forever, level 8';

Session altered.

dellera_at_ORACLE9I> select * from dual;

DUM

---
X

dellera_at_ORACLE9I> exit

$ cat oracle9i_ora_3716_yyy.trc
(snip)
ORACLE V9.2.0.5.0 - Production vsnsta=0
(snip)
*** 2004-11-11 23:16:08.383
*** SESSION ID:(10.27) 2004-11-11 23:16:08.352
APPNAME mod='SQL*Plus' mh=3669949024 act='' ah=4029777240
=====================
PARSING IN CURSOR #1 len=68 dep=0 uid=59 oct=42 lid=59 tim=2849584848
hv=2212335334 ad='68b79b4c'
alter session set events '10046 trace name context forever, level 8'
END OF STMT
EXEC #1:c=0,e=141,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=2849546124
WAIT #1: nam='SQL*Net message to client' ela= 7 p1=1413697536 p2=1
p3=0
WAIT #1: nam='SQL*Net message from client' ela= 3934965 p1=1413697536
p2=1 p3=0
=====================
PARSING IN CURSOR #1 len=18 dep=0 uid=59 oct=3 lid=59 tim=2853541197
hv=1333943659 ad='68f7c1a0'
select * from dual
END OF STMT
PARSE #1:c=0,e=924,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=2853541184
EXEC #1:c=0,e=75,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=2853563417
WAIT #1: nam='SQL*Net message to client' ela= 7 p1=1413697536 p2=1
p3=0
FETCH #1:c=0,e=97,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=4,tim=2853570443
WAIT #1: nam='SQL*Net message from client' ela= 2030 p1=1413697536
p2=1 p3=0
FETCH #1:c=0,e=4,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=2853579888
WAIT #1: nam='SQL*Net message to client' ela= 6 p1=1413697536 p2=1
p3=0
WAIT #1: nam='SQL*Net message from client' ela= 3004907 p1=1413697536
p2=1 p3=0
XCTEND rlbk=0, rd_only=1
STAT #1 id=1 cnt=1 pid=0 pos=1 obj=222 op='TABLE ACCESS FULL OBJ#(222)
'

All is well under the sun - cursor #1 closed by sqlplus on exit, STAT
dumped.

But add "alter system flush shared_pool;" in another session just
before exiting (the cursor is open at that point - sqlplus keeps open
the last cursor and closes it only when another statement is submitted
or on exit of course) and the STAT line is missing.
 
My guess is that the (recreatable) chunk(s) containing the plan in the
library cache got flushed out, and since the STAT lines contain
nothing more than the plan, they got simply skipped.

If that's correct, all it takes is a stressed library cache (eg no
bind variables) that is trapped in the vicious loop fill/flush
partially/fill again/etc and you are very likely to observe missing
STAT lines.

my 2 eurocents
Alberto Dell'Era