Striving for Optimal Performance
  • Blog
    • Archive
    • Categories
    • Search
  • Troubleshooting Oracle Performance
    • Description
    • Structure
    • Table of Contents
    • Forewords
    • Reviews
    • Downloadable Files
    • Addenda and Errata
    • First Edition
  • Public Appearances
    • Past Public Appearances
  • Contact
  • About

New Information in SQL Trace Files

21 September 2008 3 Comments Written by Christian Antognini

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.

11gR1, SQL Trace
Upcoming Speaking Engagements
Book Presentation

3 Comments

  1. Mathew Butler Mathew Butler
    21 September 2008    

    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

    Reply
  2. Christian Antognini Christian Antognini
    21 September 2008    

    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

    Reply
  3. Mathew Butler Mathew Butler
    22 September 2008    

    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.

    Reply

Leave a Reply Cancel reply

Your email address will not be published. Required fields are marked *

This site uses Akismet to reduce spam. Learn how your comment data is processed.