Sep 21 2008
New Information in SQL Trace Files
During some tests with patchset 11.1.0.7 (which is presently available for Linux 32-bit and 64-bit only) I noticed something new in the SQL trace files.
Let’s see what is the difference if I run the following statements with and without the patchset:
execute dbms_monitor.session_trace_enable(waits=>FALSE) SELECT 'Hello world!' FROM dual; execute dbms_monitor.session_trace_disable
The relevant part of the trace file is the following:
- 11.1.0.6.0
PARSING IN CURSOR #1 len=31 dep=0 uid=0 oct=3 lid=0 tim=1222018499653282 hv=1643260990 ad='6e1e6ac8' sqlid='7a45d99hz4b1y' SELECT 'Hello world!' FROM dual END OF STMT PARSE #1:c=1000,e=79,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1222018499653279 EXEC #1:c=0,e=69,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1222018499653403 FETCH #1:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1222018499653472 STAT #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)' FETCH #1:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1222018499653788
- 11.1.0.7.0
PARSING IN CURSOR #1 len=31 dep=0 uid=0 oct=3 lid=0 tim=1222018585374765 hv=1643260990 ad='6f5af5e0' sqlid='7a45d99hz4b1y' SELECT 'Hello world!' FROM dual END OF STMT PARSE #1:c=999,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1388734953,tim=1222018585374765 EXEC #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1388734953,tim=1222018585374765 FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1388734953,tim=1222018585374765 STAT #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)' FETCH #1:c=1000,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=1388734953,tim=1222018585396826 CLOSE #1:c=0,e=0,dep=0,type=0,tim=1222018585396826
You spotted the difference?
Yes! There are two fetches. But, what I wanted to point out with this post, is the new line beginning with CLOSE.
September 21st, 2008 at 10:27 pm
I see that lines associated with a cursor also have a new component “plh=”
I wonder if this is a handle to reference the source of the SQL? ie: Ease the identification of SQL sourced in the same stored procedure/package?
M
September 21st, 2008 at 10:58 pm
Hi Mathew
You are right. There is this enhancement as well. The field “plh” is the hash value of the execution plan. In other words, it matches the column plan_hash_value in v$sql_plan (and similar views…). This is an interesting information when a given SQL statement has several child cursors.
Best regards,
Chris
September 22nd, 2008 at 11:00 am
Hi Chris,
Interesting. This then adds value to tracing at level 4 (provided the cursor is still cached ),
since tracing at levels higher than 4 will already include the execution plan in the trace file.
I think I will still prefer to use level 8, or 12 when tracing. I like that all the information for analysis is tyhen captured in the one file.
Regards,
M.