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
Recent Comments