Using TKPROF for Analyzing 10046 Extended SQL Trace Files – What is Wrong with this Quote?

21 09 2011

September 21, 2011

I have written a couple of blog articles on the topic of reading 10046 extended SQL trace files.  Some of those blog articles are listed below:

Once you have collected a 10046 extended SQL trace, you can pass that trace file through TKPROF or any number of other utilities.  For example, if I pick a 10046 extended SQL trace file captured at level 8 from a 10.2.0.2 database instance and pass that file through TKPROF that is supplied with Oracle Database 11.2.0.2, a portion of the TKPROF output might appear as follows:

********************************************************************************
select currency_id, sell_rate, buy_rate,  act_material_cost, act_labor_cost, act_burden_cost, act_service_cost,
tracking_currency,
s_currency, s_thousand, i_currency, i_neg_curr, i_curr_digits,
rnd_acct_id, real_gn_acct_id, real_ls_acct_id, unreal_gn_acct_id, unreal_ls_acct_id
from INV_TRANS_CURR t, currency c
where TRANSACTION_ID = 1158316
and t.currency_id = c.id
order by c.id asc                                                                                                                                                                                                                                                                                                                          

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1      0.00       0.00          0          6          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.00       0.00          0          6          0           0

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 49 
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  NESTED LOOPS  (cr=6 pr=0 pw=0 time=125 us)
         2          2          2   TABLE ACCESS BY INDEX ROWID CURRENCY (cr=2 pr=0 pw=0 time=69 us)
         2          2          2    INDEX FULL SCAN SYS_C004588 (cr=1 pr=0 pw=0 time=37 us)(object id 12048)
         0          0          0   TABLE ACCESS BY INDEX ROWID INV_TRANS_CURR (cr=4 pr=0 pw=0 time=45 us)
         0          0          0    INDEX UNIQUE SCAN SYS_C005202 (cr=4 pr=0 pw=0 time=36 us)(object id 12327)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       5        0.00          0.00
  SQL*Net message from client                     5        0.00          0.00
  latch: library cache                            1        0.00          0.00
********************************************************************************
select euro_participant, xchg_rate from currency where id = :1             

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1      0.00       0.00          0          2          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.00       0.00          0          2          0           1

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 49 
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  TABLE ACCESS BY INDEX ROWID CURRENCY (cr=2 pr=0 pw=0 time=37 us)
         1          1          1   INDEX UNIQUE SCAN SYS_C004588 (cr=1 pr=0 pw=0 time=20 us)(object id 12048)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       5        0.00          0.00
  SQL*Net message from client                     5        0.00          0.00
  latch: library cache                            1        0.00          0.00
******************************************************************************** 

My Toy Project for Performance Tuning (otherwise known as the Hyper-Extended Oracle Performance Monitor) produces several output files when reading 10046 extended SQL trace files.  For example, if I pass in the same 10046 extended SQL trace file that was supplied to TKPROF, one of the output files contains information similar to the following that provides a detailed explanation of the running 10046 extended SQL trace file:

Statement Depth 0 (Application Code)
Cursor 62   Ver 2614   Parse at 90.371707  (0.004613)
select euro_participant, xchg_rate from currency where id = :1

Cursor 62   Ver 2614   Parse at 90.371704 (Parse to Parse -0.000003),CPU Time 0.000000,Elapsed Time 0.000034,Rows Affected 0,Blks from Buff 0,Blks from Disk 0,Goal=ALL_ROWS
Cursor 62   Ver 2614            90.371776  0.000001   SQL*Net message to client
Cursor 62   Ver 2614            90.371931  0.000137   SQL*Net message from client
Cursor 62   Ver 2614            90.372036  0.000001   SQL*Net message to client
Cursor 62   Ver 2614            90.372368  0.000297   SQL*Net message from client
Bind Variables (62):BINDS #62:  90.372368
   Bind#0
    oacdty=96 mxl=32(03) mxlc=00 mal=00 scl=00 pre=00
    oacflg=01 fl2=1000000 frm=01 csi=178 siz=32 off=0
    kxsbbbfp=6c8e4750  bln=32  avl=03  flg=05
    value="USD"

Cursor 62   Ver 2614 Execute at 90.372578 (Parse to Exec  0.000871),CPU Time 0.000000,Elapsed Time 0.000144,Rows Affected 0,Blks from Buff 0,Blks from Disk 0,
Cursor 62   Ver 2614            90.372604  0.000001   SQL*Net message to client
Cursor 62   Ver 2614            90.372757  0.000130   SQL*Net message from client
Cursor 62   Ver 2614            90.372826  0.000001   SQL*Net message to client
Cursor 62   Ver 2614   Fetch at 90.372860 (Parse to Fetch 0.001153),CPU Time 0.000000,Elapsed Time 0.000068,Rows Retrievd 1,Blks from Buff 2,Blks from Disk 0
Cursor 62   Ver 2614            90.373213  0.000301   SQL*Net message from client
Cursor 0   Ver 0            90.373330  0.000001   SQL*Net message to client
Cursor 0   Ver 0            90.375677  0.002331   SQL*Net message from client
...
Cursor 42   Ver 5 Execute at 90.384344 (Parse to Exec  81.475396),CPU Time 0.000000,Elapsed Time 0.000108,Rows Affected 0,Blks from Buff 0,Blks from Disk 0,
Cursor 42   Ver 5            90.384368  0.000001   SQL*Net message to client
Cursor 42   Ver 5            90.384532  0.000144   SQL*Net message from client
Cursor 42   Ver 5            90.384682  0.000001   SQL*Net message to client
Cursor 42   Ver 5   Fetch at 90.384739 (Parse to Fetch 81.475791),CPU Time 0.000000,Elapsed Time 0.000175,Rows Retrievd 1,Blks from Buff 11,Blks from Disk 0
Cursor 42   Ver 5            90.386534  0.001750   SQL*Net message from client
Cursor 38   Ver 2608            90.386582  0.000001   SQL*Net message to client
Cursor 38   Ver 2608            90.387369  0.000763   SQL*Net message from client
Cursor 38   Ver 2608            90.389990  0.000103   latch: library cache
----------------------------------------------------------------------------------
Statement Depth 0 (Application Code)
Cursor 38   Ver 2609   Parse at 90.391579  (0.010830)

select currency_id, sell_rate, buy_rate,  act_material_cost, act_labor_cost, act_burden_cost, act_service_cost,
tracking_currency,
s_currency, s_thousand, i_currency, i_neg_curr, i_curr_digits,
rnd_acct_id, real_gn_acct_id, real_ls_acct_id, unreal_gn_acct_id, unreal_ls_acct_id
from INV_TRANS_CURR t, currency c
where TRANSACTION_ID = 1158746
and t.currency_id = c.id
order by c.id asc

Cursor 38   Ver 2609   Parse at 90.391571 (Parse to Parse -0.000008),CPU Time 0.015625,Elapsed Time 0.004159,Rows Affected 0,Blks from Buff 0,Blks from Disk 0,**Shared Pool Misses** 1,Goal=ALL_ROWS
Cursor 38   Ver 2609            90.391738  0.000006   SQL*Net message to client
Cursor 38   Ver 2609            90.392021  0.000235   SQL*Net message from client
Cursor 38   Ver 2609            90.392118  0.000001   SQL*Net message to client
Cursor 38   Ver 2609            90.392607  0.000436   SQL*Net message from client 

A second output file from my program provides summarized information, somewhat like TKPROF:

Total for Trace File:
|PARSEs   17914|CPU S   12.546875|CLOCK S   12.487227|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         6|CUR RD BLKs (Mem)         0|SHARED POOL MISs   3281|
|EXECs    33730|CPU S    6.328125|CLOCK S    6.450126|ROWs     1348|PHY RD BLKs         0|CON RD BLKs (Mem)      8574|CUR RD BLKs (Mem)      4631|SHARED POOL MISs     27|
|FETCHs   32222|CPU S    6.546875|CLOCK S    6.436054|ROWs    27368|PHY RD BLKs         1|CON RD BLKs (Mem)    690260|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|

Wait Event Summary:
SQL*Net message to client           0.185460  On Client/Network   Min Wait:     0.000001  Avg Wait:     0.000001  Max Wait:     0.000028  Waits: 128632
SQL*Net message from client        72.674370  On Client/Network   Min Wait:     0.000112  Avg Wait:     0.000553  Max Wait:     0.016187  Waits: 131318
log file sync                       0.180988  On DB Server        Min Wait:     0.000005  Avg Wait:     0.000150  Max Wait:     0.010718  Waits:   1209
SQL*Net more data to client         0.001780  On Client/Network   Min Wait:     0.000013  Avg Wait:     0.000018  Max Wait:     0.000026  Waits:     98
db file sequential read             0.003380  On DB Server        Min Wait:     0.003380  Avg Wait:     0.003380  Max Wait:     0.003380  Waits:      1
latch: library cache                0.000256  On DB Server        Min Wait:     0.000067  Avg Wait:     0.000085  Max Wait:     0.000103  Waits:      3

Similar SQL Statements in Group: 4253 
First Reference: Cursor 62   Ver 4   Parse at 8.941502
|PARSEs    4253|CPU S    0.109375|CLOCK S    0.149414|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs     4253|CPU S    0.671875|CLOCK S    0.655012|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|FETCHs    4253|CPU S    0.468750|CLOCK S    0.295336|ROWs     4253|PHY RD BLKs         0|CON RD BLKs (Mem)      8506|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 4.92%  CLOCK S 4.33%
  *    0.000153 seconds of time related to unclassified events
  *    7.060429 seconds of time related to client/network events
----------------------------------------------------------------------------------

...
Similar SQL Statements in Group: 1 
First Reference: Cursor 18   Ver 1   Parse at 8.618896
|PARSEs       1|CPU S    0.000000|CLOCK S    0.001696|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs      486|CPU S    0.078125|CLOCK S    0.065229|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         2|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|FETCHs     486|CPU S    0.812500|CLOCK S    0.771616|ROWs        0|PHY RD BLKs         1|CON RD BLKs (Mem)    148489|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 3.50%  CLOCK S 3.30%
  *    0.003380 seconds of time related data file I/O
  *    0.197874 seconds of time related to client/network events

Similar SQL Statements in Group: 4253
|PARSEs    4253|CPU S    0.109375|CLOCK S    0.149414|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs     4253|CPU S    0.671875|CLOCK S    0.655012|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|FETCHs    4253|CPU S    0.468750|CLOCK S    0.295336|ROWs     4253|PHY RD BLKs         0|CON RD BLKs (Mem)      8506|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|

...
Statement Depth 0 (Application Code)
Cursor 62   Ver 4   Parse at 8.941502  (TD Prev 0.011920)  Similar Cnt 1
|PARSEs       1|CPU S    0.000000|CLOCK S    0.001544|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.002476|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|FETCHs       1|CPU S    0.000000|CLOCK S    0.000076|ROWs        1|PHY RD BLKs         0|CON RD BLKs (Mem)         2|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 0.00%  CLOCK S 0.02%

select euro_participant, xchg_rate from currency where id = :1

       (Rows 1)   TABLE ACCESS BY INDEX ROWID CURRENCY (cr=2 pr=0 pw=0 time=48 us)
       (Rows 1)    INDEX UNIQUE SCAN SYS_C004588 (cr=1 pr=0 pw=0 time=24 us)

Bind Variables (62):BINDS #62:  8.944672
   Bind#0
    oacdty=96 mxl=32(03) mxlc=00 mal=00 scl=00 pre=00
    oacflg=01 fl2=1000000 frm=01 csi=178 siz=32 off=0
    kxsbbbfp=36d87e78  bln=32  avl=03  flg=05
    value="USD"

------------
Statement Depth 0 (Application Code)
Cursor 4   Ver 5   Parse at 8.976105  (TD Prev 0.004661)  Similar Cnt 2
|PARSEs       1|CPU S    0.000000|CLOCK S    0.000109|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.000145|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.000071|ROWs        1|PHY RD BLKs         0|CON RD BLKs (Mem)         2|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 0.00%  CLOCK S 0.00%

select euro_participant, xchg_rate from currency where id = :1

       (Rows 1)   TABLE ACCESS BY INDEX ROWID CURRENCY (cr=2 pr=0 pw=0 time=40 us)
       (Rows 1)    INDEX UNIQUE SCAN SYS_C004588 (cr=1 pr=0 pw=0 time=20 us)

Bind Variables (4):BINDS #4:  8.976753
   Bind#0
    oacdty=96 mxl=32(03) mxlc=00 mal=00 scl=00 pre=00
    oacflg=01 fl2=1000000 frm=01 csi=178 siz=32 off=0
    kxsbbbfp=6c8e87d8  bln=32  avl=03  flg=05
    value="USD"

------------
Statement Depth 0 (Application Code)
Cursor 37   Ver 6   Parse at 9.020236  (TD Prev 0.004586)  Similar Cnt 3
|PARSEs       1|CPU S    0.000000|CLOCK S    0.000056|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.000144|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.000067|ROWs        1|PHY RD BLKs         0|CON RD BLKs (Mem)         2|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 0.00%  CLOCK S 0.00%

select euro_participant, xchg_rate from currency where id = :1

       (Rows 1)   TABLE ACCESS BY INDEX ROWID CURRENCY (cr=2 pr=0 pw=0 time=37 us)
       (Rows 1)    INDEX UNIQUE SCAN SYS_C004588 (cr=1 pr=0 pw=0 time=19 us)

Bind Variables (37):BINDS #37:  9.020884
   Bind#0
    oacdty=96 mxl=32(03) mxlc=00 mal=00 scl=00 pre=00
    oacflg=01 fl2=1000000 frm=01 csi=178 siz=32 off=0
    kxsbbbfp=6c4d08e0  bln=32  avl=03  flg=05
    value="USD"
...

Similar SQL Statements in Group: 1
|PARSEs       1|CPU S    0.015625|CLOCK S    0.003585|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.000119|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.000111|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         6|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|

Statement Depth 0 (Application Code)
Cursor 31   Ver 4   Parse at 8.922969  (TD Prev 0.014021)  Similar Cnt 1
|PARSEs       1|CPU S    0.015625|CLOCK S    0.003585|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.000119|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.000111|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         6|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 0.06%  CLOCK S 0.02%

select currency_id, sell_rate, buy_rate,  act_material_cost, act_labor_cost, act_burden_cost, act_service_cost,
tracking_currency,
s_currency, s_thousand, i_currency, i_neg_curr, i_curr_digits,
rnd_acct_id, real_gn_acct_id, real_ls_acct_id, unreal_gn_acct_id, unreal_ls_acct_id
from INV_TRANS_CURR t, currency c
where TRANSACTION_ID = 413948
and t.currency_id = c.id
order by c.id asc

       (Rows 0)   NESTED LOOPS  (cr=6 pr=0 pw=0 time=117 us)
       (Rows 2)    TABLE ACCESS BY INDEX ROWID CURRENCY (cr=2 pr=0 pw=0 time=65 us)
       (Rows 2)     INDEX FULL SCAN SYS_C004588 (cr=1 pr=0 pw=0 time=38 us)
       (Rows 0)    TABLE ACCESS BY INDEX ROWID INV_TRANS_CURR (cr=4 pr=0 pw=0 time=37 us)
       (Rows 0)     INDEX UNIQUE SCAN SYS_C005202 (cr=4 pr=0 pw=0 time=28 us) 

It is interesting to see how the contents of 10046 extended SQL trace files have evolved through the various Oracle Database release versions, yet at its core the file format has not really changed that much.  Below are a couple of examples from different Oracle Database release versions.

8.1.7.3 10046 extended SQL trace at level 8:

=====================
PARSING IN CURSOR #38 len=287 dep=0 uid=78 oct=2 lid=78 tim=370357232 hv=3536790953 ad='5ad8bec'
INSERT INTO WORK_ORDER_SCHED (SCHEDULE_ID, WORKORDER_TYPE, WORKORDER_BASE_ID, WORKORDER_SUB_ID, WORKORDER_LOT_ID, WORKORDER_SPLIT_ID, PART_ID, START_DATE, FINISH_DATE, BITS_LENGTH, SCHEDULE_TIME, PASS_COUNT, SCHEDULE_RANK) VALUES (:1, :2, :3, :4, :5, :6, :7, :8, :9, :10, :11, :12, :13)
END OF STMT
PARSE #38:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=0,tim=370357232
WAIT #38: nam='db file sequential read' ela= 0 p1=4 p2=207930 p3=1
WAIT #38: nam='db file sequential read' ela= 2 p1=9 p2=300266 p3=1
WAIT #38: nam='db file sequential read' ela= 0 p1=9 p2=350987 p3=1
WAIT #38: nam='db file sequential read' ela= 2 p1=9 p2=300330 p3=1
WAIT #38: nam='db file sequential read' ela= 0 p1=9 p2=300339 p3=1
WAIT #38: nam='db file sequential read' ela= 0 p1=9 p2=300181 p3=1
EXEC #38:c=0,e=4,p=6,cr=1,cu=12,mis=0,r=1,dep=0,og=4,tim=370357236
WAIT #38: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #38: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0
XCTEND rlbk=0, rd_only=0
WAIT #0: nam='log file sync' ela= 0 p1=1176 p2=0 p3=0
...
XCTEND rlbk=0, rd_only=0
WAIT #0: nam='log file sync' ela= 0 p1=1328 p2=0 p3=0
WAIT #0: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #0: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0
EXEC #34:c=0,e=0,p=0,cr=3,cu=2,mis=0,r=1,dep=2,og=4,tim=370537187
EXEC #34:c=0,e=0,p=0,cr=3,cu=2,mis=0,r=1,dep=2,og=4,tim=370537187
EXEC #33:c=0,e=0,p=0,cr=11,cu=8,mis=0,r=1,dep=1,og=4,tim=370537187
WAIT #33: nam='latch free' ela= 0 p1=197748644 p2=106 p3=0
WAIT #33: nam='latch free' ela= 0 p1=197748540 p2=106 p3=0
EXEC #34:c=2,e=2,p=0,cr=3,cu=2,mis=0,r=1,dep=2,og=4,tim=370537189
EXEC #34:c=0,e=0,p=0,cr=3,cu=2,mis=0,r=1,dep=2,og=4,tim=370537189
EXEC #33:c=3,e=3,p=0,cr=11,cu=8,mis=0,r=1,dep=1,og=4,tim=370537190
EXEC #39:c=3,e=3,p=0,cr=26,cu=20,mis=0,r=1,dep=0,og=4,tim=370537190
WAIT #39: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #39: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0
XCTEND rlbk=0, rd_only=0
...
WAIT #0: nam='log file sync' ela= 0 p1=583 p2=0 p3=0
WAIT #0: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #0: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0
EXEC #34:c=0,e=0,p=0,cr=3,cu=2,mis=0,r=1,dep=2,og=4,tim=370580579
EXEC #34:c=0,e=0,p=0,cr=3,cu=2,mis=0,r=1,dep=2,og=4,tim=370580579
EXEC #33:c=0,e=0,p=0,cr=10,cu=6,mis=0,r=1,dep=1,og=4,tim=370580579
EXEC #34:c=0,e=0,p=0,cr=3,cu=2,mis=0,r=1,dep=2,og=4,tim=370580579
WAIT #34: nam='latch free' ela= 0 p1=197748644 p2=106 p3=0
EXEC #34:c=0,e=0,p=0,cr=3,cu=2,mis=0,r=1,dep=2,og=4,tim=370580579
EXEC #33:c=0,e=0,p=0,cr=10,cu=6,mis=0,r=1,dep=1,og=4,tim=370580579
EXEC #39:c=0,e=0,p=0,cr=24,cu=16,mis=0,r=1,dep=0,og=4,tim=370580579
WAIT #39: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #39: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0
XCTEND rlbk=0, rd_only=0
...

9.2.0.4 10046 extended SQL trace at level 12:

PARSING IN CURSOR #40 len=118 dep=0 uid=23 oct=3 lid=23 tim=1160715895381603 hv=3290581551 ad='67afe40c'
select bits_length from CUST_ORDER_BINARY
where cust_order_id = :1              and type = :2                       
END OF STMT
EXEC #40:c=0,e=109,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1160715895381598
WAIT #40: nam='SQL*Net message to client' ela= 1 p1=1413697536 p2=1 p3=0
WAIT #40: nam='SQL*Net message from client' ela= 601 p1=1413697536 p2=1 p3=0
WAIT #40: nam='db file sequential read' ela= 20 p1=5 p2=105821 p3=1
WAIT #40: nam='SQL*Net message to client' ela= 1 p1=1413697536 p2=1 p3=0
FETCH #40:c=0,e=102,p=1,cr=3,cu=0,mis=0,r=1,dep=0,og=4,tim=1160715895382393
WAIT #40: nam='SQL*Net message from client' ela= 2276 p1=1413697536 p2=1 p3=0
BINDS #43:
 bind 0: dty=96 mxl=32(08) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=64 offset=0
   bfp=b75b4a74 bln=32 avl=08 flg=05
   value="41120-26"
 bind 1: dty=96 mxl=32(01) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=0 offset=32
   bfp=b75b4a94 bln=32 avl=01 flg=01
   value="D"
=====================
PARSING IN CURSOR #43 len=105 dep=0 uid=23 oct=3 lid=23 tim=1160715895384818 hv=3322014952 ad='67afc9fc'
select bits from CUST_ORDER_BINARY
where cust_order_id = :1              and type = :2                 
END OF STMT
EXEC #43:c=0,e=96,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1160715895384815
WAIT #43: nam='SQL*Net message to client' ela= 1 p1=1413697536 p2=1 p3=0
WAIT #43: nam='SQL*Net message from client' ela= 578 p1=1413697536 p2=1 p3=0
WAIT #43: nam='SQL*Net message to client' ela= 1 p1=1413697536 p2=1 p3=0
FETCH #43:c=0,e=38,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=4,tim=1160715895385519
WAIT #43: nam='SQL*Net message from client' ela= 7413 p1=1413697536 p2=1 p3=0
WAIT #54: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #54: nam='SQL*Net message from client' ela= 3506 p1=1413697536 p2=1 p3=0
...

10.2.0.2 10046 extended SQL trace at level 8:

EXEC #3:c=0,e=172,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=2761350071
WAIT #3: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=2761350121
WAIT #3: nam='SQL*Net message from client' ela= 151 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=2761350309
WAIT #3: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=2761350464
FETCH #3:c=0,e=178,p=0,cr=11,cu=0,mis=0,r=1,dep=0,og=1,tim=2761350529
WAIT #3: nam='SQL*Net message from client' ela= 1703 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=2761352318
WAIT #38: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=2761352422
WAIT #38: nam='SQL*Net message from client' ela= 14855 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=2761367335
WAIT #38: nam='latch: library cache' ela= 86 address=6702518304 number=214 tries=1 obj#=-1 tim=2761370634
=====================
PARSING IN CURSOR #38 len=708 dep=0 uid=49 oct=3 lid=49 tim=2761372680 hv=3811084033 ad='7a792970'
...
EXEC #42:c=0,e=108,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=2792074555
WAIT #42: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=2792074579
WAIT #42: nam='SQL*Net message from client' ela= 144 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=2792074743
WAIT #42: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=2792074893
FETCH #42:c=0,e=175,p=0,cr=11,cu=0,mis=0,r=1,dep=0,og=1,tim=2792074950
WAIT #42: nam='SQL*Net message from client' ela= 1750 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=2792076745
WAIT #38: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=2792076793
WAIT #38: nam='SQL*Net message from client' ela= 763 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=2792077580
WAIT #38: nam='latch: library cache' ela= 103 address=6702518304 number=214 tries=1 obj#=-1 tim=2792080201
=====================
PARSING IN CURSOR #38 len=709 dep=0 uid=49 oct=3 lid=49 tim=2792081790 hv=332841952 ad='6553b430'
...
WAIT #3: nam='SQL*Net message from client' ela= 132 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=2792095443
WAIT #3: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=2792096040
FETCH #3:c=15625,e=634,p=0,cr=11,cu=0,mis=0,r=1,dep=0,og=1,tim=2792096110
WAIT #3: nam='SQL*Net message from client' ela= 1645 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=2792097829
WAIT #62: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=2792097885
WAIT #62: nam='SQL*Net message from client' ela= 779 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=2792098689
WAIT #62: nam='latch: library cache' ela= 67 address=6702518784 number=214 tries=1 obj#=-1 tim=2792099425
=====================
PARSING IN CURSOR #62 len=709 dep=0 uid=49 oct=3 lid=49 tim=2792102933 hv=3211547247 ad='59a46098'

11.2.0.2 10046 extended SQL trace at level 8:

PARSING IN CURSOR #395158696 len=44 dep=0 uid=62 oct=42 lid=62 tim=279105099708 hv=1347470086 ad='0' sqlid='5pgz5gt851hs6'
ALTER SESSION SET OPTIMIZER_INDEX_COST_ADJ=5
END OF STMT
PARSE #395158696:c=0,e=32,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=279105099708
EXEC #395158696:c=0,e=33,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=279105099773
WAIT #395158696: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=0 tim=279105099786
WAIT #395158696: nam='SQL*Net message from client' ela= 29739 driver id=1413697536 #bytes=1 p3=0 obj#=0 tim=279105129537
*** SESSION ID:(4.2401) 2011-08-18 11:30:18.997

CLOSE #395158696:c=0,e=6,dep=0,type=0,tim=279105130224
=====================
PARSING IN CURSOR #395158696 len=66 dep=0 uid=62 oct=3 lid=62 tim=279105130999 hv=1053158396 ad='7ffa55c7da0' sqlid='f2q5x9szcbuzw'
SELECT
  ID,
  DESCRIPTION
FROM
  T90
WHERE
  ID BETWEEN 1 AND 400
END OF STMT
PARSE #395158696:c=0,e=745,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=3691735591,tim=279105130998
EXEC #395158696:c=0,e=23,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3691735591,tim=279105131072
WAIT #395158696: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=0 tim=279105131099
WAIT #395158696: nam='db file sequential read' ela= 145 file#=4 block#=15211 blocks=1 obj#=70282 tim=279105131283
WAIT #395158696: nam='db file sequential read' ela= 141 file#=4 block#=3048038 blocks=1 obj#=70282 tim=279105131458
WAIT #395158696: nam='db file sequential read' ela= 124 file#=4 block#=15212 blocks=1 obj#=70282 tim=279105131606
WAIT #395158696: nam='db file sequential read' ela= 127 file#=4 block#=26658 blocks=1 obj#=69278 tim=279105131769
FETCH #395158696:c=0,e=676,p=4,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=3691735591,tim=279105131790
WAIT #395158696: nam='SQL*Net message from client' ela= 68 driver id=1413697536 #bytes=1 p3=0 obj#=69278 tim=279105131879
WAIT #395158696: nam='db file parallel read' ela= 1187 files=1 blocks=39 requests=39 obj#=69278 tim=279105133171
WAIT #395158696: nam='db file sequential read' ela= 140 file#=4 block#=26704 blocks=1 obj#=69278 tim=279105133374
WAIT #395158696: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=69278 tim=279105133394
WAIT #395158696: nam='db file parallel read' ela= 1372 files=1 blocks=39 requests=39 obj#=69278 tim=279105134838
WAIT #395158696: nam='db file sequential read' ela= 128 file#=4 block#=32056 blocks=1 obj#=69278 tim=279105135092
WAIT #395158696: nam='db file parallel read' ela= 652 files=1 blocks=19 requests=19 obj#=69278 tim=279105135796
WAIT #395158696: nam='db file sequential read' ela= 142 file#=4 block#=106517 blocks=1 obj#=69278 tim=279105136038
FETCH #395158696:c=0,e=4182,p=100,cr=101,cu=0,mis=0,r=100,dep=0,og=1,plh=3691735591,tim=279105136084
...
WAIT #395158696: nam='db file parallel read' ela= 539 files=1 blocks=16 requests=16 obj#=69278 tim=279193197874
WAIT #395158696: nam='db file sequential read' ela= 123 file#=4 block#=3692381 blocks=1 obj#=69278 tim=279193198082
FETCH #395158696:c=0,e=2238,p=57,cr=58,cu=0,mis=0,r=57,dep=0,og=1,plh=3691735591,tim=279193198120
STAT #395158696 id=1 cnt=2547158 pid=0 pos=1 obj=69278 op='TABLE ACCESS BY INDEX ROWID T90 (cr=2573591 pr=2070791 pw=0 time=3919404 us cost=202973 size=216021546 card=4000399)'
STAT #395158696 id=2 cnt=2547158 pid=1 pos=1 obj=70282 op='INDEX RANGE SCAN IND_T90 (cr=30646 pr=5238 pw=0 time=891170 us cost=426 size=0 card=4071715)'
WAIT #395158696: nam='SQL*Net message from client' ela= 13470 driver id=1413697536 #bytes=1 p3=0 obj#=69278 tim=279193211655

While reading the Oracle 11g Performance Tuning Recipes book I have found a number of interesting bits of information.  For example, at the bottom of page 334 and the top of page 335 is the following interesting quote:

“A locking situation is a good example where you can visually inspect a raw trace file. TKPROF doesn’t provide you details about latches and locks (enqueues). If you suspect that a query was waiting on a lock, digging deep into a raw trace file shows you exactly where and why a query was waiting. In the WAIT line, the elapsed time (ela) shows the amount of time waited (in microseconds).”

What, if anything, is wrong with the above quote from the book?

The point of blog articles like this one is not to insult authors who have spent thousands of hours carefully constructing an accurate and helpful book, but instead to suggest that readers investigate when something stated does not exactly match what one believes to be true.  It could be that the author “took a long walk down a short pier”, or that the author is revealing accurate information which simply cannot be found through other resources (and may in the process be directly contradicting information sources you have used in the past).  If you do not investigate in such cases, you may lose an important opportunity to learn something that could prove to be extremely valuable.


Actions

Information

6 responses

21 09 2011
Mladen Gogala

Charles, 10046 doesn’t show you the reason. It only shows wait events, without any particular details. Locking contention can only be explored while it lasts, by digging into V$LOCK table and V$SESSION to find out the object, file, block and row that is being waited on. This quote is plain wrong.
PS:
—–
After our little debate on CDOS, I added your blog to my mandatory reading list.

21 09 2011
Charles Hooper

Mladen,

Thanks for stopping by and providing a helpful comment on the blog article. You made valid points and backed up those points with a suggested alternative (one of the planned outcomes of these types of blog article).

I initially read the quote quite a bit differently than you, and thus came up with a very different comment about what is right or wrong about the quote. I will share the portion of my book review for this recipe in roughly 24-48 hours – until then I will try to limit my comments in this article. Obviously, one of the other planned outcomes of these types of articles is to tap into the vast combined knowledge of readers so that we may build a much more complete picture of how things work than I could put together by myself.

21 09 2011
Charles Hooper

Maybe some hints for a third possible interpretation of the quoted section from the book, with the help of the Oracle Database documentation library:
http://download.oracle.com/docs/cd/E14072_01/server.112/e10713/consist.htm#BABHIGGC

•A row is locked only when modified by a writer.
•A writer of a row blocks a concurrent writer of the same row.
•A reader never blocks a writer.
•A writer never blocks a reader.

http://download.oracle.com/docs/cd/A57673_01/DOC/server/doc/A48506/sqlconce.htm#1288

Queries are different from other types of SQL statements because they return data as results if they are successful. Whereas other statements return simply success or failure, a query can return one row or thousands of rows. The results of a query are always in tabular format, and the rows of the result are fetched (retrieved), either a row at a time or in groups.

http://download.oracle.com/docs/cd/B28359_01/server.111/b28318/sqlplsql.htm#CNCPT1914

Queries are different from other types of SQL statements because, if successful, they return data as results. Whereas other statements simply return success or failure, a query can return one row or thousands of rows. The results of a query are always in tabular format, and the rows of the result are fetched (retrieved), either a row at a time or in groups.

22 09 2011
Charles Hooper

I thought for sure that there were be at least ten comments attached to this blog article by now.

As I mentioned, there are a couple of different potential interpretations of the quoted section from the book.

The book’s recipes jump around a bit, back and forth between topics. For example, page 340 also discusses using TKPROF to analyze 10046 extended SQL trace files time, where the book states: “time: Total time (in milliseconds) spent processing the operation”. So, are the “ela” statistics reported in microseconds while the “time” statistics in the Row Source Execution Plan are shown in milliseconds, or do the two time statistics both measure time in 1/1,000,000 of a second (the 1,000,000 could be rounded up to the nearest power of two on some operating system platforms and Oracle Database release versions). Does it matter if the reader has one Oracle 8i (8.1.7.4, for example) database as well as an assortment of 9i, 10g, and 11g R2 databases?

You could also focus on the phrase “a query was waiting on a lock”… when would a SELECT statement (using the definition from the Oracle Database Concepts guide, query… to ask a question of the database) wait on a lock? Of course, readers do not block other readers, readers do not block writers, and writers do not block readers. A SELECT FOR UPDATE might need to wait on an enqueue, but the “FOR UPDATE” clause likely does not represent common usage in a query for most applications. If you focus on the phrase “where and why a query was waiting”, as Mladen pointed out, the WHY might not be present in a 10046 extended SQL trace for a session (maybe if you compared simultaneously captured 10046 traces for multiple sessions you would find the WHY).

The following shows how I selected to interpret the quoted section, and the fule full recipe for that matter, for the book review:

Recipe 10-6 states the following, “Note that the TKPROF or other profiling tools show the elapsed times for various phases of query execution, but not the information for locks and latches. If you’re trying to find out if any locks are slowing down a query, look at the raw trace files to see if there are any enqueue waits in the WAIT lines of the raw file.” I might be misinterpreting these two sentences, but the sentences appear to be incorrect assuming that a level 8 or greater (wait events) extended SQL trace, generated by Oracle Database 10.1 (or higher), is passed into TKPROF. Starting in Oracle Database 10.1 most of the enqueue waits are divided into much more specific wait events that begin with “enq:” (there are 299 wait events in Oracle Database 11.2.0.2 that begin with “enq:”). The same is true for latches, where the “latch free” wait event is split out into multiple wait events (there are 43 wait events in Oracle Database 11.2.0.2 for latches). (pages 335-336)

Any other comments?

24 09 2011
Gary Myers (@syd_oracle)

The term ‘query’ can be fuzzy. Does it refer to just SELECT or does an UPDATE or DELETE imply the data is being queried. How about the SELECT part of an INSERT …SELECT ? Is a SELECT…FOR UPDATE ‘just’ a query ? It only requires SELECT permissions, not UPDATE.

The quotes from the documentation are outdated. The RETURNING clause of INSERTs, UPDATEs and DELETEs return a result set as well as success/failure. They’ve always returned the number of rows affected too.

So I think it may be a case of what is wrong with the quotes from the Oracle documentation :)

28 09 2011
Charles Hooper

Another documentation bug? – I think that would be #5 or #6 that have been mentioned on this blog by various people. :-)

The book was heading in the right direction, but completely missed the opportunity to demonstrate something that is useful. This recipe was about 10046 extended SQL traces, and thus apparently could not offer in the recipe format a demonstration of how what was statement might work, or offer an alternative such as that offered by Mladen above.

The multiple interpretations of the quoted section of the book probably was not intentional, but it can lead to some confusion. I agree that the term “query” is fuzzy. Does one “query” a witness to determine what happened, or does one “query” a witness to change what happened?

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: