Brain Teaser: 10046 Extended SQL Trace Shows “EXEC #435118472:c=15600,e=510″, How is that Possible?

14 04 2011

April 14, 2011

I find interesting details from time to time about Oracle Database.  I am in the process of organizing material for a presentation, and I encountered something interesting when testing Oracle Database 11.2.0.2 with patch 3 applied.  I traced the execution of an application and then processed the 660MB  trace file using a trace file profiler that I created.  A portion of my trace file profiler’s output looks like this:

Statement Depth 0 (Application Code)
Cursor 27   Ver 1   Parse at 170.113677 SQL_ID='aw9mpsx4pyta2'  (TD Prev 25.179488)  Similar Cnt 1
|PARSEs       1|CPU S    0.000000|CLOCK S    0.000491|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs    82848|CPU S   25.849376|CLOCK S   26.046921|ROWs    82848|PHY RD BLKs       560|CON RD BLKs (Mem)    248703|CUR RD BLKs (Mem)     84702|SHARED POOL MISs      1|
|FETCHs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 20.68%  CLOCK S 20.47%
|                ++++||                ++++|
UPDATE REQUIREMENT SET REQUIRED_DATE = :1 WHERE WORKORDER_TYPE = :2 AND WORKORDER_BASE_ID = :3 AND WORKORDER_SUB_ID = :4
 AND WORKORDER_LOT_ID = :5 AND WORKORDER_SPLIT_ID = :6 AND OPERATION_SEQ_NO = :7 AND PIECE_NO = :8

       (Rows 0)   UPDATE  REQUIREMENT (cr=3 pr=2 pw=0 time=861 us)
       (Rows 1)    INDEX UNIQUE SCAN SYS_C0025561 (cr=3 pr=2 pw=0 time=754 us cost=2 size=33 card=1

The above output shows that this SQL statement, which was executed 82,848 times, consumed a total of 25.85 seconds of CPU time and 26.05 second for the elapsed time.  This SQL statement accounted for 20.68% of the total CPU consumption found in the trace file, and 20.47% of the total elapsed time found in the trace file.  The execution plan displayed is from the first execution of the SQL statement, which is output by default after the first execution starting with Oracle Database 11.1.  Since this SQL statement consumed twice as much CPU and elapsed time as the second highest consumer, I thought that I would take a look in the raw 10046 trace file to see what is happening.  Among other things, I was attempting to determine if there is a time consuming row-level trigger that is firing on each execution, which then caused another row-level trigger to fire.

Here is a portion of that trace file which shows two executions of the SQL statement:

PARSING IN CURSOR #435118472 len=219 dep=0 uid=70 oct=6 lid=70 tim=150927664059 hv=1230988610 ad='466efdfb8' sqlid='aw9mpsx4pyta2'
UPDATE REQUIREMENT SET REQUIRED_DATE = :1 WHERE WORKORDER_TYPE = :2 AND WORKORDER_BASE_ID = :3 AND WORKORDER_SUB_ID = :4
 AND WORKORDER_LOT_ID = :5 AND WORKORDER_SPLIT_ID = :6 AND OPERATION_SEQ_NO = :7 AND PIECE_NO = :8
END OF STMT
PARSE #435118472:c=0,e=491,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=150927664059
WAIT #435118472: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=150927664110
WAIT #435118472: nam='SQL*Net message from client' ela= 364 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=150927664488
...
WAIT #435118472: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=81989 tim=150927704272
WAIT #435118472: nam='SQL*Net message from client' ela= 284 driver id=1413697536 #bytes=1 p3=0 obj#=81989 tim=150927704573
BINDS #435118472:
 Bind#0
  oacdty=96 mxl=32(16) mxlc=00 mal=00 scl=00 pre=00
  oacflg=01 fl2=1000000 frm=01 csi=178 siz=256 off=0
  kxsbbbfp=0532a410  bln=32  avl=16  flg=05
  value="2011-04-20-0:0:0"
 Bind#1
  oacdty=96 mxl=32(01) mxlc=00 mal=00 scl=00 pre=00
  oacflg=01 fl2=1000000 frm=01 csi=178 siz=0 off=32
  kxsbbbfp=0532a430  bln=32  avl=01  flg=01
  value="W"
 Bind#2
  oacdty=96 mxl=32(05) mxlc=00 mal=00 scl=00 pre=00
  oacflg=01 fl2=1000000 frm=01 csi=178 siz=0 off=64
  kxsbbbfp=0532a450  bln=32  avl=05  flg=01
  value="16750"
 Bind#3
  oacdty=96 mxl=32(03) mxlc=00 mal=00 scl=00 pre=00
  oacflg=01 fl2=1000000 frm=01 csi=178 siz=0 off=96
  kxsbbbfp=0532a470  bln=32  avl=03  flg=01
  value="200"
 Bind#4
  oacdty=96 mxl=32(01) mxlc=00 mal=00 scl=00 pre=00
  oacflg=01 fl2=1000000 frm=01 csi=178 siz=0 off=128
  kxsbbbfp=0532a490  bln=32  avl=01  flg=01
  value="1"
 Bind#5
  oacdty=96 mxl=32(01) mxlc=00 mal=00 scl=00 pre=00
  oacflg=01 fl2=1000000 frm=01 csi=178 siz=0 off=160
  kxsbbbfp=0532a4b0  bln=32  avl=01  flg=01
  value="0"
 Bind#6
  oacdty=96 mxl=32(02) mxlc=00 mal=00 scl=00 pre=00
  oacflg=01 fl2=1000000 frm=01 csi=178 siz=0 off=192
  kxsbbbfp=0532a4d0  bln=32  avl=02  flg=01
  value="20"
 Bind#7
  oacdty=96 mxl=32(02) mxlc=00 mal=00 scl=00 pre=00
  oacflg=01 fl2=1000000 frm=01 csi=178 siz=0 off=224
  kxsbbbfp=0532a4f0  bln=32  avl=02  flg=01
  value="30"
EXEC #435118472:c=0,e=300,p=0,cr=3,cu=1,mis=0,r=1,dep=0,og=1,plh=755874150,tim=150927704902
WAIT #435118472: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=81989 tim=150927704977
WAIT #435118472: nam='SQL*Net message from client' ela= 177 driver id=1413697536 #bytes=1 p3=0 obj#=81989 tim=150927705171
BINDS #435118472:
 Bind#0
  oacdty=96 mxl=32(16) mxlc=00 mal=00 scl=00 pre=00
  oacflg=01 fl2=1000000 frm=01 csi=178 siz=256 off=0
  kxsbbbfp=0532a410  bln=32  avl=16  flg=05
  value="2011-04-20-0:0:0"
 Bind#1
  oacdty=96 mxl=32(01) mxlc=00 mal=00 scl=00 pre=00
  oacflg=01 fl2=1000000 frm=01 csi=178 siz=0 off=32
  kxsbbbfp=0532a430  bln=32  avl=01  flg=01
  value="W"
...
 Bind#7
  oacdty=96 mxl=32(02) mxlc=00 mal=00 scl=00 pre=00
  oacflg=01 fl2=1000000 frm=01 csi=178 siz=0 off=224
  kxsbbbfp=0532a4f0  bln=32  avl=02  flg=01
  value="40"
EXEC #435118472:c=15600,e=510,p=0,cr=3,cu=1,mis=0,r=1,dep=0,og=1,plh=755874150,tim=150927705707
WAIT #435118472: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=81989 tim=150927705800
WAIT #435118472: nam='SQL*Net message from client' ela= 1217 driver id=1413697536 #bytes=1 p3=0 obj#=81989 tim=150927707038 

Looking at the above, you may see a couple of odd items.  First, the cursor number is not 27 as was indicated in my trace file profiler’s output – it is instead the huge number 435,118,472.  Tanel Poder provided an explanation of this change which was introduced in Oracle Database 11.2.0.2 here – that change initially caused a lot of problems for my trace file profiler which in hindsight made the silly assumption that no session would have more than 5,000 or 10,000 open cursors (which would thus result in cursors numbers below 10,000).

What I thought that the casual observer might find interesting is this line in the trace file:

EXEC #435118472:c=15600,e=510,p=0,cr=3,cu=1,mis=0,r=1,dep=0,og=1,plh=755874150,tim=150927705707

The above line indicates that the instance consumed 0.015600 seconds of CPU time in a 0.000510 second time period - a bit of an unusual feat to see the CPU consumption 30 times greater than the elapsed time considering that this SQL statement was not executed in parallel.  Is there a clue why this happened?  Take a look at the trace file line that shows the previous execution:

EXEC #435118472:c=0,e=300,p=0,cr=3,cu=1,mis=0,r=1,dep=0,og=1,plh=755874150,tim=150927704902 

This time the elapsed time is 300 / 0 times longer than the CPU time.  So now the brain teaser: if the CPU time is 30 times (15600 / 510) greater than the elapsed time, and then the elapsed time is infinitely (300 / 0) longer than the CPU time, how is it possible that the overall CPU time for this SQL statement is roughly the same as the overall elapsed time?  (On a side note, you might wonder if this could compound into odd time reporting errors if different SQL statements are executed in between the executions of this SQL statement.)

Just for fun, here is the TKPROF output for this SQL statement:

SQL ID: aw9mpsx4pyta2 Plan Hash: 755874150

UPDATE REQUIREMENT SET REQUIRED_DATE = :1
WHERE
 WORKORDER_TYPE = :2 AND WORKORDER_BASE_ID = :3 AND WORKORDER_SUB_ID = :4 AND
  WORKORDER_LOT_ID = :5 AND WORKORDER_SPLIT_ID = :6 AND OPERATION_SEQ_NO = :7
  AND PIECE_NO = :8

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute  82848     25.84      26.04        556     248550      84702       82848
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    82849     25.84      26.04        556     248550      84702       82848

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

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  UPDATE  REQUIREMENT (cr=3 pr=2 pw=0 time=861 us)
         1          1          1   INDEX UNIQUE SCAN SYS_C0025561 (cr=3 pr=2 pw=0 time=754 us cost=2 size=33 card=1)(object id 81989)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                   82849        0.00          0.10
  SQL*Net message from client                 82849        0.00         19.33
  db file sequential read                        95        0.00          0.03
  db file scattered read                         95        0.00          0.04 







Follow

Get every new post delivered to your Inbox.

Join 137 other followers