10046 Extended SQL Trace Interpretation 2

26 01 2010

January 26, 2010 

(Back to the Previous Post in the Series) (Forward to the Next Post in the Series)

In an earlier blog article I described several methods for enabling and disabling 10046 extended SQL traces, listed several keywords that are found in 10046 traces, and demonstrated output generated by my Toy Project for Performance Tuning as it processed the raw trace file. 

Another way to enable a 10046 trace for a session is through the use of a logon trigger created by the SYS user.  For example, the following trigger will enable a 10046 trace at level 12 for any program that begins with the letters MS or VB, even if the path to the program is included in the PROGRAM column of V$SESSION.  With the use of DECODE, it is very easy to allow the trigger to enable tracing for an additional list of programs: 

CREATE OR REPLACE TRIGGER LOGON_10046_TRACE AFTER LOGON ON DATABASE
DECLARE
  SHOULD_EXECUTE INTEGER;
BEGIN
  SELECT DECODE(SUBSTR(UPPER(PROGRAM),1,2),'MS',1,'VB',1,0)
      +DECODE(INSTR(PROGRAM,'\',-1),0,0,DECODE(SUBSTR(UPPER(SUBSTR(PROGRAM,INSTR(PROGRAM,'\',-1)+1)),1,2),'MS',1,'VB',1,0))
    INTO SHOULD_EXECUTE FROM V$SESSION
    WHERE SID=(SELECT SID FROM V$MYSTAT WHERE ROWNUM=1);
  IF SHOULD_EXECUTE > 0 THEN
    EXECUTE IMMEDIATE 'ALTER SESSION SET EVENTS ''10046 TRACE NAME CONTEXT FOREVER, LEVEL 12''';
  END IF;
END;
/

Obviously, if you create the trigger, you should drop the trigger when it is no longer needed using the following command. 

DROP TRIGGER LOGON_10046_TRACE;

Let’s try creating a test trace file with Oracle Database 10.2.0.4.  First, we need to create a couple of test tables with 10,000 rows each and collect statistics for the tables and primary key indexes: 

CREATE TABLE T1 (
  C1 NUMBER,
  C2 VARCHAR2(255),
  PRIMARY KEY (C1));

CREATE TABLE T2 (
  C1 NUMBER,
  C2 VARCHAR2(255),
  PRIMARY KEY (C1));

INSERT INTO
  T1
SELECT
  ROWNUM,
  RPAD(TO_CHAR(ROWNUM),255,'A')
FROM
  DUAL
CONNECT BY
  LEVEL<=10000;

INSERT INTO
  T2
SELECT
  ROWNUM,
  RPAD(TO_CHAR(ROWNUM),255,'A')
FROM
  DUAL
CONNECT BY
  LEVEL<=10000;

COMMIT;

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1',CASCADE=>TRUE)
EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T2',CASCADE=>TRUE)

We now have two tables, each with 10,000 rows.  This test case in SQL*Plus will:

  1. Flush the buffer cache (twice) to force physical reads
  2. Set the fetch array size to the SQL*Plus default value of 15 rows per fetch call
  3. Disable output of the rows returned from the database to limit client-side delays
  4. Create two bind variables with the value of 1 and 2
  5. Enable a 10046 extended SQL trace at level 12
  6. Give the trace file an easy to identify name
  7. Execute a query that joins the two tables
  8. Increases the fetch array size to 50 rows per fetch call
  9. Increase the value of the second bind variable from 2 to 10,000
  10. Execute the same SQL statement executed in step 7 
ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

SET ARRAYSIZE 15
SET AUTOTRACE TRACEONLY STATISTICS

VARIABLE N1 NUMBER
VARIABLE N2 NUMBER

EXEC :N1 := 1
EXEC :N2 := 2

EXEC DBMS_SESSION.SESSION_TRACE_ENABLE(WAITS=>TRUE, BINDS=>TRUE)
ALTER SESSION SET TRACEFILE_IDENTIFIER='10046_FIND_ME';

SELECT
  T1.C1,
  T2.C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SET ARRAYSIZE 50
EXEC :N1 := 1
EXEC :N2 := 10000

SELECT
  T1.C1,
  T2.C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2;

SELECT SYSDATE FROM DUAL;

EXEC DBMS_SESSION.SESSION_TRACE_DISABLE;

Rather than scrolling all of the rows on the screen, SQL*Plus output the following from the two executions: 

Statistics
---------------------------------------------------
          1  recursive calls
          0  db block gets
          9  consistent gets
          5  physical reads
          0  redo size
        921  bytes sent via SQL*Net to client
        334  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          2  rows processed

Statistics
---------------------------------------------------
          0  recursive calls
          0  db block gets
      10982  consistent gets
        404  physical reads
          0  redo size
    2647906  bytes sent via SQL*Net to client
       2523  bytes received via SQL*Net from client
        201  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
      10000  rows processed

From the above, the first execution required 9 consistent block gets, and 5 of those block gets involved reading the block from disk.  The server sent 921 bytes to the client in 2 round trips, and 2 rows were retrieved.  2 round trips (we will see why later)?  The second execution required 10,982 consistent block gets, and 404 of those involved physical reads.  The server sent about 2.53MB to the client in 10,000 rows, using 201 round trips.  Nice, but we can find out more about what happened.

We could process the trace file with tkprof using a command like this: 

tkprof testdb_ora_4148_10046_find_me.trc testdb_ora_4148_10046_find_me.txt

A portion of the TKPROF output might look like this (see Metalink Doc ID 41634.1 for help with reading the tkprof output): 

********************************************************************************
count    = number of times OCI procedure was executed
cpu      = cpu time in seconds executing
elapsed  = elapsed time in seconds executing
disk     = number of physical reads of buffers from disk
query    = number of buffers gotten for consistent read
current  = number of buffers gotten in current mode (usually for update)
rows     = number of rows processed by the fetch or execute call
********************************************************************************

SELECT
  T1.C1,
  T2.C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.00          0          0          0           0
Execute      3      0.00       0.00          0          0          0           0
Fetch      203      0.28       0.38        409      10991          0       10002
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      208      0.28       0.38        409      10991          0       10002

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 31 

Rows     Row Source Operation
-------  ---------------------------------------------------
      2  FILTER  (cr=9 pr=5 pw=0 time=19577 us)
      2   NESTED LOOPS  (cr=9 pr=5 pw=0 time=19569 us)
      2    TABLE ACCESS BY INDEX ROWID T2 (cr=5 pr=3 pw=0 time=13843 us)
      2     INDEX RANGE SCAN SYS_C0020548 (cr=3 pr=2 pw=0 time=9231 us)(object id 114211)
      2    INDEX UNIQUE SCAN SYS_C0020547 (cr=4 pr=2 pw=0 time=5788 us)(object id 114210)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                     204        0.00          0.00
  db file sequential read                       409        0.00          0.21
  SQL*Net message from client                   204        0.00          0.07
  SQL*Net more data to client                  1200        0.00          0.02

The above is a nice summary of what was found in the trace file for our specific test SQL statement, but what is it telling us?  There were 2 parse calls (1 for each execution), and one of those parse calls resulted in a hard parse.  There were 3 execution calls (I am only able to explain 2 of the execution calls).  There were 203 fetch calls that retrieved a total of 10,002 rows - from this we could derive that on average the client fetched 49.27 rows per fetch call.  All of the time for the execution happened on the fetch calls, which required 0.28 seconds of CPU time and a total of 0.38 clock seconds to execute.  A total of 10,991 consistent gets were required and 409 blocks were read from disk. 

The execution plan displayed is a little misleading, since it shows that only 2 rows were retrieved (note that if this example were executed on Oracle 11.1.0.6 or higher, the first and second executions of the SQL statement could have had different execution plans).  An index range scan is performed on the index SYS_C0020548 (the primary key index for table T2) to locate all of the C1 values between 1 and 2 – note that the optimizer used transitive closure here since the restriction in the SQL statement was actually placed on the column C1 of table T1.  The top line in the plan indicates that in total the query required 9 consistent gets, 5 physical block reads, and 0.019577 seconds to execute.  The index range scan on SYS_C0020548 required 3 consistent gets, and 2 physical block reads were required to satisfy the 3 consistent gets.  Table T2 required an additional 2 consistent gets and 1 physical block read.  A nested loop operation was performed, driving into the primary key index for table T1 – this required an additional 4 consistent gets and 2 physical block reads.  But, what about the second execution of the SQL statement?

The wait events show 409 waits on the “db file sequential read” wait event, which indicates physically reading 1 block at a time from disk - note that this exactly matches the “disk” column in the “fetch” line of the tkprof summary.  Every block that had to be read from disk was read one block at a time, with an average read time of 0.000513 seconds per block read (the extremely fast average time likely indicate caching of blocks at the file system, RAID controller, SAN, or hard drive).  There were 1200 waits on the “SQL*Net more data to client” wait, indicating that the SDU size was filled 1200 times when sending the data to the client computer.

We could also run the trace file though my Toy Project (below is one of 4 outputs from my program): 

Total for Trace File:
|PARSEs       6|CPU S    0.000000|CLOCK S    0.008073|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      4|
|EXECs        6|CPU S    0.015625|CLOCK S    0.007978|ROWs        3|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      2|
|FETCHs     205|CPU S    0.281250|CLOCK S    0.382338|ROWs    10003|PHY RD BLKs       409|CON RD BLKs (Mem)     10991|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|

Wait Event Summary:
SQL*Net message to client           0.000318  On Client/Network   Min Wait:     0.000001  Avg Wait:     0.000001  Max Wait:     0.000005
SQL*Net message from client         3.916585  On Client/Network   Min Wait:     0.000211  Avg Wait:     0.018302  Max Wait:     3.829540
db file sequential read             0.211736  On DB Server        Min Wait:     0.000182  Avg Wait:     0.000518  Max Wait:     0.005905
SQL*Net more data to client         0.020220  On Client/Network   Min Wait:     0.000010  Avg Wait:     0.000017  Max Wait:     0.000258

Total for Similar SQL Statements in Each Group:
----------------------------------------------------------------------------------
Similar SQL Statements in Group: 2
|PARSEs       2|CPU S    0.000000|CLOCK S    0.001231|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs        2|CPU S    0.000000|CLOCK S    0.004237|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|FETCHs     203|CPU S    0.281250|CLOCK S    0.382314|ROWs    10002|PHY RD BLKs       409|CON RD BLKs (Mem)     10991|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 94.74%  CLOCK S 97.34%
  *    0.211736 seconds of time related data file I/O
  *    0.096212 seconds of time related to client/network events
| +++++++++++++++++++|| +++++++++++++++++++|

Cursor 3   Ver 1   Parse at 0.000000  Similar Cnt 1
|PARSEs       1|CPU S    0.000000|CLOCK S    0.001113|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs        1|CPU S    0.000000|CLOCK S    0.003538|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|FETCHs       2|CPU S    0.015625|CLOCK S    0.019769|ROWs        2|PHY RD BLKs         5|CON RD BLKs (Mem)         9|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 5.26%  CLOCK S 6.13%
|                   +||                   +|
SELECT
  T1.C1,
  T2.C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2

       (Rows 2)   FILTER  (cr=9 pr=5 pw=0 time=19577 us)
       (Rows 2)    NESTED LOOPS  (cr=9 pr=5 pw=0 time=19569 us)
       (Rows 2)     TABLE ACCESS BY INDEX ROWID T2 (cr=5 pr=3 pw=0 time=13843 us)
       (Rows 2)      INDEX RANGE SCAN SYS_C0020548 (cr=3 pr=2 pw=0 time=9231 us)
       (Rows 2)     INDEX UNIQUE SCAN SYS_C0020547 (cr=4 pr=2 pw=0 time=5788 us)

Bind Variables:BINDS #3:  -0.000008
   Bind#0
    oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
    oacflg=03 fl2=1000000 frm=00 csi=00 siz=48 off=0
    kxsbbbfp=13ce8870  bln=22  avl=02  flg=05
    value=1
   Bind#1
    oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
    oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=24
    kxsbbbfp=13ce8888  bln=22  avl=02  flg=01
    value=2

------------
Cursor 4   Ver 1   Parse at 0.041427  (TD Prev 0.007600)  Similar Cnt 2
|PARSEs       1|CPU S    0.000000|CLOCK S    0.000118|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.000699|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|FETCHs     201|CPU S    0.265625|CLOCK S    0.362545|ROWs    10000|PHY RD BLKs       404|CON RD BLKs (Mem)     10982|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 89.47%  CLOCK S 91.21%
|  ++++++++++++++++++||  ++++++++++++++++++|
SELECT
  T1.C1,
  T2.C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2

   (Rows 10000)   FILTER  (cr=10982 pr=404 pw=0 time=680024 us)
   (Rows 10000)    NESTED LOOPS  (cr=10982 pr=404 pw=0 time=670018 us)
   (Rows 10000)     TABLE ACCESS BY INDEX ROWID T2 (cr=781 pr=387 pw=0 time=590006 us)
   (Rows 10000)      INDEX RANGE SCAN SYS_C0020548 (cr=218 pr=17 pw=0 time=10038 us)
   (Rows 10000)     INDEX UNIQUE SCAN SYS_C0020547 (cr=10201 pr=17 pw=0 time=77882 us)

Bind Variables:BINDS #4:  0.041421
   Bind#0
    oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
    oacflg=03 fl2=1000000 frm=00 csi=00 siz=48 off=0
    kxsbbbfp=13ce8870  bln=22  avl=02  flg=05
    value=1
   Bind#1
    oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
    oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=24
    kxsbbbfp=13ce8888  bln=22  avl=02  flg=01
    value=10000
----------------------------------------------------------------------------------

The above shows basically the same output as tkprof, just with greater resolution, both sets of bind variables, and both sets of execution plans.

We could also use any number of other 10046 trace file parsers including TRCANLZR (see Metalink Doc ID 224270.1), TVD$XTAT (see the book “Troubleshooting Oracle Performance”), ESQLTRCPROF (see the book “Secrets of the Oracle Database”), the Hotsos Profiler (Method R), OraSRP (www.oracledba.ru/orasrp/), or one of several other programs.

I typically either look at the output from my program or the raw 10046 trace file.  That brings us to the raw 10046 trace file.  So, what does the raw output of the trace file look like?  Before diving into the raw trace file, let’s find a little information to help us later:

COLUMN TABLE_NAME FORMAT A10

SELECT
  TABLE_NAME,
  INDEX_NAME
FROM
  DBA_INDEXES
WHERE
  TABLE_NAME IN ('T1','T2')
ORDER BY
  TABLE_NAME;

TABLE_NAME INDEX_NAME
---------- ------------
T1         SYS_C0020547
T2         SYS_C0020548

COLUMN OBJECT_NAME FORMAT A15

SELECT
  OBJECT_ID,
  OBJECT_NAME,
  OBJECT_TYPE
FROM
  DBA_OBJECTS
WHERE
  OBJECT_NAME IN ('T1','T2','SYS_C0020547','SYS_C0020548')
ORDER BY
  OBJECT_NAME;

 OBJECT_ID OBJECT_NAME     OBJECT_TYPE
---------- --------------- -----------
    114210 SYS_C0020547    INDEX
    114211 SYS_C0020548    INDEX
    114209 T1              TABLE
    114207 T2              TABLE

From the above output, the index on table T1 is named SYS_C0020547 and it has an OBJECT_ID of 114210.  The index on table T2 is named SYS_C0020548 and it has an OBJECT_ID of 114211.  Table T1 has an OBJECT_ID of 114209, and table T2 has an OBJECT_ID of 114207.  Now on to a portion of the raw 10046 trace file:

=====================
PARSING IN CURSOR #3 len=91 dep=0 uid=31 oct=3 lid=31 tim=4963261335 hv=3021110247 ad='982ab100'
SELECT
  T1.C1,
  T2.C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2
END OF STMT
PARSE #3:c=0,e=1113,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=4963261327
BINDS #3:
kkscoacd
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=48 off=0
  kxsbbbfp=13ce8870  bln=22  avl=02  flg=05
  value=1
 Bind#1
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=24
  kxsbbbfp=13ce8888  bln=22  avl=02  flg=01
  value=2

From the above, we see that the first parse was a hard parse that required 0 CPU seconds and 0.001113 clock seconds.  Additionally, two bind variables were passed in.  A level 4 or level 12 10046 extended SQL trace file will include the submitted bind variable values, as shown above.  It is possible to use the following list to decode the bind variable data type (oacdty), in the process determining that the bind variables are in fact, defined as numbers.  See Metalink Doc IDs 67701.1 and 154170.1, the Oracle OCI documentation, or Julian Dyke’s site for a more complete list of datatype constants: 

  0 - This row is a placeholder for a procedure with no arguments.
  1 - VARCHAR2 (or NVARCHAR)
  2 - NUMBER
  3 - NATIVE INTEGER (for PL/SQL's BINARY_INTEGER)
  8 - LONG
 11 - ROWID
 12 - DATE
 23 - RAW
 24 - LONG RAW
 96 - CHAR (or NCHAR)
112 - CLOB or NCLOB
113 - BLOB
114 - BFILE
106 - MLSLABEL
250 - PL/SQL RECORD
251 - PL/SQL TABLE
252 - PL/SQL BOOLEAN

The trace file continues below:

EXEC #3:c=0,e=3538,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=4963265927
WAIT #3: nam='SQL*Net message to client' ela= 5 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=4963266031
WAIT #3: nam='db file sequential read' ela= 4816 file#=4 block#=1138316 blocks=1 obj#=114211 tim=4963271120
WAIT #3: nam='db file sequential read' ela= 3934 file#=4 block#=1138318 blocks=1 obj#=114211 tim=4963275219
WAIT #3: nam='db file sequential read' ela= 4443 file#=4 block#=1138310 blocks=1 obj#=114207 tim=4963279805
WAIT #3: nam='db file sequential read' ela= 5221 file#=4 block#=1093148 blocks=1 obj#=114210 tim=4963285172
WAIT #3: nam='db file sequential read' ela= 236 file#=4 block#=1093150 blocks=1 obj#=114210 tim=4963285569
FETCH #3:c=15625,e=19589,p=5,cr=5,cu=0,mis=0,r=1,dep=0,og=1,tim=4963285717
WAIT #3: nam='SQL*Net message from client' ela= 364 driver id=1413697536 #bytes=1 p3=0 obj#=114210 tim=4963286240
WAIT #3: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=114210 tim=4963286494
FETCH #3:c=0,e=180,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,tim=4963286588

Above, we see the 5 physical block reads of blocks 1138316 and 1138318 of  OBJECT_ID 114211 (index on table T2, SYS_C0020548), followed by a single block read of OBJECT_ID 114207 (table T2), and 2 single block reads of object 114210 (index on table T1, SYS_C0020547) – note that the final of the 5 physical block reads completed in 0.000236 seconds, which is about 20 times faster than the time it takes for 1 revolution of a 15,000 RPM hard drive platter.  The first fetch call returned a single row, even though the array fetch size was explicitly set to 15 rows.  That fetch required 5 consistent gets, which then required the 5 physical block reads.  The 1 row was sent to the client which then fetched a second row  (4963286588 – 4963286240 4963285717)/1,000,000 =  0.000348 0.000871 seconds later.  The trace file continues:

WAIT #3: nam='SQL*Net message from client' ela= 319 driver id=1413697536 #bytes=1 p3=0 obj#=114210 tim=4963287035
*** SESSION ID:(211.17427) 2010-01-25 15:41:01.540
STAT #3 id=1 cnt=2 pid=0 pos=1 obj=0 op='FILTER  (cr=9 pr=5 pw=0 time=19577 us)'
STAT #3 id=2 cnt=2 pid=1 pos=1 obj=0 op='NESTED LOOPS  (cr=9 pr=5 pw=0 time=19569 us)'
STAT #3 id=3 cnt=2 pid=2 pos=1 obj=114207 op='TABLE ACCESS BY INDEX ROWID T2 (cr=5 pr=3 pw=0 time=13843 us)'
STAT #3 id=4 cnt=2 pid=3 pos=1 obj=114211 op='INDEX RANGE SCAN SYS_C0020548 (cr=3 pr=2 pw=0 time=9231 us)'
STAT #3 id=5 cnt=2 pid=2 pos=2 obj=114210 op='INDEX UNIQUE SCAN SYS_C0020547 (cr=4 pr=2 pw=0 time=5788 us)'
WAIT #0: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=114210 tim=4963289021
WAIT #0: nam='SQL*Net message from client' ela= 2329 driver id=1413697536 #bytes=1 p3=0 obj#=114210 tim=4963291420
=====================

Cursor #3 was closed, so Oracle output the STAT (row source operation) lines, as we saw in the tkprof output.  The trace file continues (with a couple of lines removed):

...
=====================
PARSING IN CURSOR #4 len=91 dep=0 uid=31 oct=3 lid=31 tim=4963302762 hv=3021110247 ad='982ab100'
SELECT
  T1.C1,
  T2.C2
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C1 BETWEEN :N1 AND :N2
END OF STMT
PARSE #4:c=0,e=118,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=4963302756
BINDS #4:
kkscoacd
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=48 off=0
  kxsbbbfp=13ce8870  bln=22  avl=02  flg=05
  value=1
 Bind#1
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=24
  kxsbbbfp=13ce8888  bln=22  avl=02  flg=01
  value=10000
EXEC #4:c=0,e=699,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=4963304299
WAIT #4: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=114210 tim=4963304383
FETCH #4:c=0,e=94,p=0,cr=5,cu=0,mis=0,r=1,dep=0,og=1,tim=4963304564
WAIT #4: nam='SQL*Net message from client' ela= 718 driver id=1413697536 #bytes=1 p3=0 obj#=114210 tim=4963305403
WAIT #4: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=114210 tim=4963305590
WAIT #4: nam='SQL*Net more data to client' ela= 29 driver id=1413697536 #bytes=2146 p3=0 obj#=114210 tim=4963305766
WAIT #4: nam='SQL*Net more data to client' ela= 20 driver id=1413697536 #bytes=1862 p3=0 obj#=114210 tim=4963305913
WAIT #4: nam='SQL*Net more data to client' ela= 17 driver id=1413697536 #bytes=2128 p3=0 obj#=114210 tim=4963306065
WAIT #4: nam='db file sequential read' ela= 2272 file#=4 block#=1138311 blocks=1 obj#=114207 tim=4963308471
WAIT #4: nam='SQL*Net more data to client' ela= 27 driver id=1413697536 #bytes=1868 p3=0 obj#=114207 tim=4963308686
WAIT #4: nam='SQL*Net more data to client' ela= 18 driver id=1413697536 #bytes=2122 p3=0 obj#=114207 tim=4963308841
WAIT #4: nam='SQL*Net more data to client' ela= 13 driver id=1413697536 #bytes=2128 p3=0 obj#=114207 tim=4963309001
FETCH #4:c=0,e=3573,p=1,cr=54,cu=0,mis=0,r=50,dep=0,og=1,tim=4963309109

Note that there was no hard parse this time.  The first two fetches are complete at this point.  Again, the first fetch returned a single row, while the second fetch returned 50 rows.  Note the presence of the “SQL*Net more data to client” wait before the second fetch line printed – each of these lines indicates that the SDU size was filled on the previous send to the client.  Notice that there was only a single physical block read of OBJECT_ID 114207 (table T2), requiring 0.002272 seconds, when fetching the first 51 rows (the other blocks were already in the buffer cache).  The trace file continues below:

WAIT #4: nam='SQL*Net message from client' ela= 256 driver id=1413697536 #bytes=1 p3=0 obj#=114207 tim=4963309476
WAIT #4: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=114207 tim=4963309654
WAIT #4: nam='db file sequential read' ela= 226 file#=4 block#=1138312 blocks=1 obj#=114207 tim=4963309995
WAIT #4: nam='SQL*Net more data to client' ela= 32 driver id=1413697536 #bytes=2116 p3=0 obj#=114207 tim=4963310197
WAIT #4: nam='SQL*Net more data to client' ela= 14 driver id=1413697536 #bytes=2096 p3=0 obj#=114207 tim=4963310353
WAIT #4: nam='SQL*Net more data to client' ela= 13 driver id=1413697536 #bytes=1834 p3=0 obj#=114207 tim=4963310488
WAIT #4: nam='db file sequential read' ela= 1762 file#=4 block#=1138308 blocks=1 obj#=114207 tim=4963312390
WAIT #4: nam='SQL*Net more data to client' ela= 23 driver id=1413697536 #bytes=2096 p3=0 obj#=114207 tim=4963312551
WAIT #4: nam='SQL*Net more data to client' ela= 16 driver id=1413697536 #bytes=2096 p3=0 obj#=114207 tim=4963312783
WAIT #4: nam='SQL*Net more data to client' ela= 13 driver id=1413697536 #bytes=1834 p3=0 obj#=114207 tim=4963312904
FETCH #4:c=0,e=3345,p=2,cr=55,cu=0,mis=0,r=50,dep=0,og=1,tim=4963312955

Two more physical block reads of OBJECT_ID 114207 (table T2) to return the next 50 rows to the client.  Jumping forward in the trace file to the last two fetches:

...
FETCH #4:c=0,e=1259,p=2,cr=55,cu=0,mis=0,r=50,dep=0,og=1,tim=4963757700
WAIT #4: nam='SQL*Net message from client' ela= 842 driver id=1413697536 #bytes=1 p3=0 obj#=114207 tim=4963758586
WAIT #4: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=114207 tim=4963758653
WAIT #4: nam='SQL*Net more data to client' ela= 16 driver id=1413697536 #bytes=2124 p3=0 obj#=114207 tim=4963758766
WAIT #4: nam='db file sequential read' ela= 242 file#=4 block#=1773782 blocks=1 obj#=114207 tim=4963759071
WAIT #4: nam='SQL*Net more data to client' ela= 17 driver id=1413697536 #bytes=2104 p3=0 obj#=114207 tim=4963759182
WAIT #4: nam='SQL*Net more data to client' ela= 13 driver id=1413697536 #bytes=1841 p3=0 obj#=114207 tim=4963759268
WAIT #4: nam='SQL*Net more data to client' ela= 17 driver id=1413697536 #bytes=2104 p3=0 obj#=114207 tim=4963759365
WAIT #4: nam='SQL*Net more data to client' ela= 13 driver id=1413697536 #bytes=1841 p3=0 obj#=114207 tim=4963759453
WAIT #4: nam='db file sequential read' ela= 226 file#=4 block#=1773852 blocks=1 obj#=114207 tim=4963759715
WAIT #4: nam='SQL*Net more data to client' ela= 20 driver id=1413697536 #bytes=2104 p3=0 obj#=114207 tim=4963759867
FETCH #4:c=0,e=1290,p=2,cr=54,cu=0,mis=0,r=49,dep=0,og=1,tim=4963759912

From the above, we see that Oracle is still performing an average of two single block physical reads per fetch call, and the final fetch call retrieved just 49 rows.  The trace file continues:

WAIT #4: nam='SQL*Net message from client' ela= 792 driver id=1413697536 #bytes=1 p3=0 obj#=114207 tim=4963760775
*** SESSION ID:(211.17427) 2010-01-25 15:41:02.008
STAT #4 id=1 cnt=10000 pid=0 pos=1 obj=0 op='FILTER  (cr=10982 pr=404 pw=0 time=680024 us)'
STAT #4 id=2 cnt=10000 pid=1 pos=1 obj=0 op='NESTED LOOPS  (cr=10982 pr=404 pw=0 time=670018 us)'
STAT #4 id=3 cnt=10000 pid=2 pos=1 obj=114207 op='TABLE ACCESS BY INDEX ROWID T2 (cr=781 pr=387 pw=0 time=590006 us)'
STAT #4 id=4 cnt=10000 pid=3 pos=1 obj=114211 op='INDEX RANGE SCAN SYS_C0020548 (cr=218 pr=17 pw=0 time=10038 us)'
STAT #4 id=5 cnt=10000 pid=2 pos=2 obj=114210 op='INDEX UNIQUE SCAN SYS_C0020547 (cr=10201 pr=17 pw=0 time=77882 us)'
WAIT #0: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=114207 tim=4963764774
WAIT #0: nam='SQL*Net message from client' ela= 2789 driver id=1413697536 #bytes=1 p3=0 obj#=114207 tim=4963767585

From the above, we see the execution plan for the second execution – this information was missing from the tkprof output.  A hash join with two full table scans probably would have been more efficient than a nested loop join with index lookups, especially if the number of rows were larger.  This is one of the potential problems with using bind variables, especially when bind variable peeking is enabled (by default in recent releases) – the execution plan is essentially locked after the initial hard parse.  Oracle 11.1.0.6 introduced a feature known as adaptive cursor sharing that could potentially alter the plan on a future execution if Oracle senses that there will be significant changes in the number of rows returned when different bind variable values are submitted.

Incidentally, you may have noticed the keyword “oct” on the “PARSING IN CURSOR” lines in the above trace file.  This keyword identifies the Oracle command type, which is related to the V$SESSION.COMMAND column and the V$SQL.COMMAND_TYPE column. Common command type values include: 

  1 - CREATE TABLE
  2 - INSERT
  3 - SELECT
  6 - UPDATE
  7 - DELETE
  9 - CREATE INDEX

See the “Command Column of V$SESSION and Corresponding Commands” table in the Oracle Reference documentation (Table 8-2 in the Oracle Database Reference 11g Release 2 book) for a complete list of command types.

For more information about 10046 trace files, see Chapter 8, “Understanding Performance Optimization Methods”, in the book “Expert Oracle Practices: Oracle Database Administration from the Oak Table” (the chapter was co-written by Randolf Geist and myself).  The book “Optimizing Oracle Performance” is also highly recommended.


Actions

Information

One response

20 02 2010
Blogroll Report 22/01/2009 – 29/01/2010 « Coskan’s Approach to Oracle

[...] 14-How to read 10046 raw trace file? Charles Hooper-10046 Extended SQL Trace Interpretation 2 [...]

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s




Follow

Get every new post delivered to your Inbox.

Join 139 other followers

%d bloggers like this: