10046 Extended SQL Trace Interpretation

December 1, 2009

(Forward to the Next Post in the Series)

10046 extended SQL trace files provide a significant level of detail specific to a single session.  Extended SQL traces are enabled by setting event 10046 to level 4 (bind variables), level 8 (wait events), or level 12 (bind variables and wait events).  There are several methods that may be used to set event 10046, partially dependent on the Oracle release version, and whether or not the event may be set interactively within the session:

  ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12';
-or-
  EXEC SYS.DBMS_SYSTEM.SET_EV(SID,SERIAL#,10046,12,'');
-or-
  EXEC SYS.DBMS_SUPPORT.START_TRACE_IN_SESSION(SID,SERIAL#,WAITS=>TRUE,BINDS=>FALSE);
-or-
  EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE(SESSION_ID=>SID,SERIAL_NUM=>SERIAL#,WAITS=>TRUE,BINDS=>TRUE)
-or-
  EXEC SYS.DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(SID,SERIAL#,TRUE);

The SID and SERIAL# may be retrieved from V$SESSION for the session of interest.  The SYS.DBMS_SYSTEM.SET_EV method is unsupported, but it works fine on older versions of Oracle where the other methods do not exist.  Not all of the above methods work in older Oracle releases.  Oracle will create the trace files in the server’s udump directory (or the trace directory with release 11.1.0.6 and later).  A logon trigger may be used to enable a 10046 extended SQL trace, possibly enabling a trace for all sessions that start the same program, or for a specific user.  10046 traces may also be enabled with the SQL*Plus ORADEBUG functionality.

Before executing any of the above commands (especially if enabled using an ALTER SYSTEM method), determine how to disable a 10046 trace, depending on how it was started:

  ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';
-or-
  EXEC SYS.DBMS_SYSTEM.SET_EV(SID,SERIAL#,10046,0,'');
-or-
  EXEC SYS.DBMS_SUPPORT.STOP_TRACE_IN_SESSION(SID,SERIAL#);
-or-
  EXEC SYS.DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(SID,SERIAL#,FALSE);

A short summary of several keywords found in a 10046 extended SQL trace file:
len= the number of characters in the SQL statement
dep= tells the application/trigger depth at which the SQL statement was executed. dep=0 indicates that it was executed by the client application. dep=1 indicates that the SQL statement was executed by a trigger, the Oracle optimizer, or a space management call. dep=2 indicates that the SQL statement was called from a trigger, dep=3 indicates that the SQL statement was called from a trigger that was called from a trigger.
tim= is a time stamp measured in 1/1,000,000 of a second that may be used for tracking the progress in the 10046 trace file – take the delta value of the most recent tim=, subtract the first tim=, divide the result by 1,000,000 – equals the number of seconds into the trace file.
c= CPU seconds – amount of CPU resources required at that point in the execution. On 8.1.7.4 and earlier, divide by 100 to obtain the number of seconds. After 8.1.7.4, divide by 1,000,000 to obtain the number of seconds.
e= Elapsed seconds – number of seconds as measured by a high precision clock at that point in the execution. This may be significantly different from CPU seconds. On 8.1.7.4 and earlier, divide by 100 to obtain the number of seconds. After 8.1.7.4, divide by 1,000,000 to obtain the number of seconds.
p= Physical blocks read from disk.
cr= Consistent reads
cu= Consistent reads in current mode
mis= Number of shared pool misses at that stage of execution.
r= Number of rows returned by the call
og= Optimizer goal – 1=ALL_ROWS, 2=FIRST_ROWS (and FIRST_ROWS_n), 3=RULE, 4=CHOOSE
XCTEND rlbk=0 indicates that the client issued a COMMIT, rd_only=1 indicates that no information changed in the database as a result of the COMMIT
ela= is the elapsed time in 1/100 of a second on 8.1.7.4 and earlier, and in 1/1,000,000 of a second on versions after 8.1.7.4.
p1= meaning depends on the wait event
p2= meaning depends on the wait event
p3= meaning depends on the wait event

STAT lines – the row source execution plan:
id= line identifier
cnt= number of rows returned or processed
pid= parent operation identifier – used to determine indentation of the plan
obj= object id of the object referenced at that stage of the plan

Putting the pieces together, it is possible to do the following analysis of a raw 10046 extended SQL trace file:

PARSING IN CURSOR #12 len=170 dep=0 uid=31 oct=3 lid=31 tim=768609360 hv=205969412 ad='a64cba88'
SELECT C1 , SUBSTR(C2,1,20) C2  FROM T7 WHERE   
  EXISTS ( 
    SELECT 
      1 
    FROM 
      T8 
    WHERE 
      T8.C1=T7.C1)
  AND T7.C1 BETWEEN :1 AND :2
END OF STMT
PARSE #12:c=0,e=29,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=768609356
BINDS #12:
kkscoacd
 Bind#0
  oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
  oacflg=00 fl2=1000010 frm=00 csi=178 siz=48 off=0
  kxsbbbfp=151423d0  bln=22  avl=02  flg=05
  value=1
 Bind#1
  oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
  oacflg=00 fl2=1000010 frm=00 csi=178 siz=0 off=24
  kxsbbbfp=151423e8  bln=22  avl=03  flg=01
  value=81000
EXEC #12:c=0,e=807,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=768611110
WAIT #12: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=114176 tim=768611226
WAIT #12: nam='db file sequential read' ela= 184 file#=4 block#=1779171 blocks=1 obj#=114178 tim=768611561
WAIT #12: nam='db file scattered read' ela= 213 file#=4 block#=1779172 blocks=5 obj#=114178 tim=768612046
WAIT #12: nam='db file sequential read' ela= 103 file#=4 block#=1138380 blocks=1 obj#=114177 tim=768612399
WAIT #12: nam='db file sequential read' ela= 87 file#=4 block#=1754469 blocks=1 obj#=114177 tim=768612648
WAIT #12: nam='db file sequential read' ela= 88 file#=4 block#=1138382 blocks=1 obj#=114177 tim=768612865
WAIT #12: nam='db file sequential read' ela= 81 file#=4 block#=1138374 blocks=1 obj#=114176 tim=768613103
FETCH #12:c=0,e=2195,p=10,cr=51,cu=0,mis=0,r=14,dep=0,og=1,tim=768613513
WAIT #12: nam='SQL*Net message from client' ela= 3432 driver id=1413697536 #bytes=1 p3=0 obj#=114176 tim=768617150
STAT #12 id=1 cnt=14 pid=0 pos=1 obj=0 op='FILTER  (cr=51 pr=10 pw=0 time=2170 us)'
STAT #12 id=2 cnt=14 pid=1 pos=1 obj=0 op='NESTED LOOPS  (cr=51 pr=10 pw=0 time=2137 us)'
STAT #12 id=3 cnt=14 pid=2 pos=1 obj=0 op='SORT UNIQUE (cr=7 pr=6 pw=0 time=984 us)'
STAT #12 id=4 cnt=14 pid=3 pos=1 obj=114178 op='TABLE ACCESS FULL T8 (cr=7 pr=6 pw=0 time=900 us)'
STAT #12 id=5 cnt=14 pid=2 pos=2 obj=114176 op='TABLE ACCESS BY INDEX ROWID T7 (cr=44 pr=4 pw=0 time=1131 us)'
STAT #12 id=6 cnt=14 pid=5 pos=1 obj=114177 op='INDEX UNIQUE SCAN SYS_C0020535 (cr=30 pr=3 pw=0 time=820 us)'

A simple walk through of the trace file, mapping the trace file to a timeline (this is output from my Toy Project for Performance Tuning):

Cursor 12   Ver 1   Parse at 0.000000
SELECT C1 , SUBSTR(C2,1,20) C2  FROM T7 WHERE   
  EXISTS ( 
    SELECT 
      1 
    FROM 
      T8 
    WHERE 
      T8.C1=T7.C1)
  AND T7.C1 BETWEEN :1 AND :2

Cursor 12   Ver 1   Parse at -0.000004 (Parse to Parse -0.000004),CPU Time 0.000000,
            Elapsed Time 0.000029,Rows Affected 0,Blks from Buff 0,Blks from Disk 0,Goal=ALL_ROWS
Bind Variables:BINDS #12:  -0.000004
   Bind#0
    oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
    oacflg=00 fl2=1000010 frm=00 csi=178 siz=48 off=0
    kxsbbbfp=151423d0  bln=22  avl=02  flg=05
    value=1
   Bind#1
    oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
    oacflg=00 fl2=1000010 frm=00 csi=178 siz=0 off=24
    kxsbbbfp=151423e8  bln=22  avl=03  flg=01
    value=81000

Cursor 12   Ver 1 Execute at 0.001750 (Parse to Exec  0.001750),CPU Time 0.000000,
            Elapsed Time 0.000807,Rows Affected 0,Blks from Buff 0,Blks from Disk 0,
Cursor 12   Ver 1            0.001866  0.000004   SQL*Net message to client
Cursor 12   Ver 1            0.002201  0.000184   db file sequential read
Cursor 12   Ver 1            0.002686  0.000213   db file scattered read
Cursor 12   Ver 1            0.003039  0.000103   db file sequential read
Cursor 12   Ver 1            0.003288  0.000087   db file sequential read
Cursor 12   Ver 1            0.003505  0.000088   db file sequential read
Cursor 12   Ver 1            0.003743  0.000081   db file sequential read
Cursor 12   Ver 1   Fetch at 0.004153 (Parse to Fetch 0.004153),CPU Time 0.000000,
            Elapsed Time 0.002195,Rows Retrievd 14,Blks from Buff 51,Blks from Disk 10
Cursor 12   Ver 1            0.007790  0.003432   SQL*Net message from client

Sometimes mapping the trace file to a timeline is not the best approach, but understanding the role of a specific SQL statement is more critical to understanding the cause of a performance problem (this is output from my Toy Project for Performance Tuning):

Similar SQL Statements in Group: 1
|PARSEs 1|CPU S 0.000000|CLOCK S 0.000029|ROWs  0|PHY RD BLKs  0|CON RD BLKs (Mem)  0|CUR RD BLKs (Mem) 0|SHARED POOL MISs 0|
|EXECs  1|CPU S 0.000000|CLOCK S 0.000807|ROWs  0|PHY RD BLKs  0|CON RD BLKs (Mem)  0|CUR RD BLKs (Mem) 0|SHARED POOL MISs 0|
|FETCHs 1|CPU S 0.000000|CLOCK S 0.002195|ROWs 14|PHY RD BLKs 10|CON RD BLKs (Mem) 51|CUR RD BLKs (Mem) 0|SHARED POOL MISs 0|

Cursor 12   Ver 1   Parse at 0.000000  Similar Cnt 1
|PARSEs 1|CPU S 0.000000|CLOCK S 0.000029|ROWs  0|PHY RD BLKs  0|CON RD BLKs (Mem)  0|CUR RD BLKs (Mem) 0|SHARED POOL MISs 0|
|EXECs  1|CPU S 0.000000|CLOCK S 0.000807|ROWs  0|PHY RD BLKs  0|CON RD BLKs (Mem)  0|CUR RD BLKs (Mem) 0|SHARED POOL MISs 0|
|FETCHs 1|CPU S 0.000000|CLOCK S 0.002195|ROWs 14|PHY RD BLKs 10|CON RD BLKs (Mem) 51|CUR RD BLKs (Mem) 0|SHARED POOL MISs 0|
  CLOCK S 98.67%
|++++++++++++++++++++|

SELECT C1 , SUBSTR(C2,1,20) C2  FROM T7 WHERE   
  EXISTS ( 
    SELECT 
      1 
    FROM 
      T8 
    WHERE 
      T8.C1=T7.C1)
  AND T7.C1 BETWEEN :1 AND :2

      (Rows 14)   FILTER  (cr=51 pr=10 pw=0 time=2170 us)
      (Rows 14)    NESTED LOOPS  (cr=51 pr=10 pw=0 time=2137 us)
      (Rows 14)     SORT UNIQUE (cr=7 pr=6 pw=0 time=984 us)
      (Rows 14)      TABLE ACCESS FULL T8 (cr=7 pr=6 pw=0 time=900 us)
      (Rows 14)     TABLE ACCESS BY INDEX ROWID T7 (cr=44 pr=4 pw=0 time=1131 us)
      (Rows 14)      INDEX UNIQUE SCAN SYS_C0020535 (cr=30 pr=3 pw=0 time=820 us)

Bind Variables:BINDS #12:  -0.000004
   Bind#0
    oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
    oacflg=00 fl2=1000010 frm=00 csi=178 siz=48 off=0
    kxsbbbfp=151423d0  bln=22  avl=02  flg=05
    value=1
   Bind#1
    oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
    oacflg=00 fl2=1000010 frm=00 csi=178 siz=0 off=24
    kxsbbbfp=151423e8  bln=22  avl=03  flg=01
    value=81000

Of course, if the STATISTICS_LEVEL parameter is set to ALL, or a GATHER_PLAN_STATISTICS hint is provided, the following will retrieve the actual execution plan for the test query, if executed immediately after the test query:

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'))

The output of the above for this SQL statement follows:

SQL_ID  bkhdgq864dq04, child number 0
-------------------------------------
SELECT C1 , SUBSTR(C2,1,20) C2  FROM T7 WHERE       EXISTS (       SELECT         1       FROM         T8       WHERE        
T8.C1=T7.C1)    AND T7.C1 BETWEEN :1 AND :2

Plan hash value: 1996673128

--------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                     | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |  OMem |  1Mem | Used-Mem |
--------------------------------------------------------------------------------------------------------------------------------------------
|*  1 |  FILTER                       |              |      1 |        |     14 |00:00:00.01 |      51 |     10 |       |       |          |
|   2 |   NESTED LOOPS                |              |      1 |      1 |     14 |00:00:00.01 |      51 |     10 |       |       |          |
|   3 |    SORT UNIQUE                |              |      1 |      1 |     14 |00:00:00.01 |       7 |      6 |  9216 |  9216 | 8192  (0)|
|*  4 |     TABLE ACCESS FULL         | T8           |      1 |      1 |     14 |00:00:00.01 |       7 |      6 |       |       |          |
|   5 |    TABLE ACCESS BY INDEX ROWID| T7           |     14 |      1 |     14 |00:00:00.01 |      44 |      4 |       |       |          |
|*  6 |     INDEX UNIQUE SCAN         | SYS_C0020535 |     14 |      1 |     14 |00:00:00.01 |      30 |      3 |       |       |          |
--------------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(:1<=:2)
   4 - filter(("T8"."C1">=:1 AND "T8"."C1"<=:2))
   6 - access("T8"."C1"="T7"."C1")
       filter(("T7"."C1"<=:2 AND "T7"."C1">=:1))

The raw 10046 Extended SQL trace offers several advantages over the DBMS_XPLAN output if the P1, P2, and P3 values from the wait events are examined closely:

nam='db file scattered read' ela= 213 file#=4 block#=1779172 blocks=5 obj#=114178 tim=768612046

In the above, a multi-block read from disk requiring 0.000213 seconds of absolute file number 4, starting at block 1779172, and extending for 5 blocks was performed.  The blocks belong to object ID 114178 and happened at the trace file’s sequential time of 768612046, which may be referenced to the sequential time of other lines in the trace file.

Much more information about 10046 extended SQL traces is provided in the the chapters I co-wrote for the “Expert Oracle Practices: Oracle Database Administration from the Oak Table” book.