Search My Oracle Blog

Custom Search

29 March, 2008

Example "sliced" trace files and tkprof

Referring to my previous posting , here is a [small] case study :

Assume that this SQL file represents the "Application Server" process that ran 2 SQL statements twice each :

select o.id, o.name from my_order_test o, my_source_tab s
where o.name=s.object_name
and o.id > 57000
order by o.id
/
rem run another statement to close the cursor
select count(*) from to_shrink;

pause pausing here to simulate a wait (what happens is that an index get's dropped)


select o.id, o.name from my_order_test o, my_source_tab s
where o.name=s.object_name
and o.id > 57000
order by o.id
/
rem run another statement to close the cursor
select count(*) from to_shrink;

rem Completed


Assume that a developer actually dropped an index (MY_ORDER_TEST_NDX_1) while the first execution of the query on "TO_SHRINK" was runing [I put a pause in to allow me enough time to drop the index from another session]. In that case, the execution plan for the first SQL statement (joing "MY_ORDER_TEST" with "MY_SOURCE_TAB") would change from the first execution to the second.

Would a tkprof listing show me the two execution plans ?

Here is the tkprof listing for the full (2 executions of 2 SQLs) run of the simulated "Application Server") :


select o.id, o.name from my_order_test o, my_source_tab s
where o.name=s.object_name
and o.id > 57000
order by o.id

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.07 0.08 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2 0.03 0.04 0 3424 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.10 0.12 0 3424 0 0

Misses in library cache during parse: 2
Optimizer mode: ALL_ROWS
Parsing user id: 64

Rows Row Source Operation
------- ---------------------------------------------------
0 SORT ORDER BY (cr=3 pr=0 pw=0 time=388 us)
0 HASH JOIN (cr=3 pr=0 pw=0 time=358 us)
0 TABLE ACCESS BY INDEX ROWID MY_ORDER_TEST (cr=3 pr=0 pw=0 time=60 us)
0 INDEX RANGE SCAN MY_ORDER_TEST_NDX_1 (cr=3 pr=0 pw=0 time=47 us)(object id 57002)
0 TABLE ACCESS FULL MY_SOURCE_TAB (cr=0 pr=0 pw=0 time=0 us)


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 2 0.00 0.00
SQL*Net message from client 2 0.00 0.01
********************************************************************************

select count(*)
from
to_shrink


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 4 0.00 0.01 0 998 0 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 8 0.00 0.02 0 998 0 2

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 64

Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=499 pr=0 pw=0 time=10927 us)
33100 TABLE ACCESS FULL TO_SHRINK (cr=499 pr=0 pw=0 time=99382 us)


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 4 0.00 0.00
SQL*Net message from client 4 12.70 22.95



********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 4 0.07 0.08 0 0 0 0
Execute 4 0.00 0.00 0 0 0 0
Fetch 6 0.03 0.06 0 4422 0 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 14 0.10 0.14 0 4422 0 2

Misses in library cache during parse: 2

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 6 0.00 0.00
SQL*Net message from client 6 12.70 22.96


Notice that tkprof does tell me that there were 2 executions of the first SQL statement (joining MY_ORDER_TEST with MY_SOURCE_TAB) and, also, that it was parsed twice, it does not indicate that there were 2 different execution plans used. It presents Row Sources Operations for only the first execution -- the one with the index present.
The fact that the second execution of the same SQL resulted in a FullTableScan of MY_ORDER_TEST isn't immediately visible.

Since I have a suspicion that tkprof isn't (or is unable to) presenting the "complete truth", [there were a total of 3,424 consistent gets but the RowSourceOperations list shows only 3 blocks in "cr" mode !] I split up the raw trace file and run seperate tkprofs. I throw away the header of the trace file.

Thus, for example, I create "Partial_1.trc" as :


PARSING IN CURSOR #2 len=115 dep=0 uid=64 oct=3 lid=64 tim=101226877659 hv=1396900901 ad='2ae90eec'
select o.id, o.name from my_order_test o, my_source_tab s
where o.name=s.object_name
and o.id > 57000
order by o.id
END OF STMT
PARSE #2:c=0,e=2024,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=101226877649
EXEC #2:c=0,e=119,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=101226924421
WAIT #2: nam='SQL*Net message to client' ela= 7 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=101226926138
FETCH #2:c=0,e=374,p=0,cr=3,cu=0,mis=0,r=0,dep=0,og=1,tim=101226928013
WAIT #2: nam='SQL*Net message from client' ela= 4980 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=101226934787
STAT #2 id=1 cnt=0 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=3 pr=0 pw=0 time=388 us)'
STAT #2 id=2 cnt=0 pid=1 pos=1 obj=0 op='HASH JOIN (cr=3 pr=0 pw=0 time=358 us)'
STAT #2 id=3 cnt=0 pid=2 pos=1 obj=56926 op='TABLE ACCESS BY INDEX ROWID MY_ORDER_TEST (cr=3 pr=0 pw=0 time=60 us)'
STAT #2 id=4 cnt=0 pid=3 pos=1 obj=57002 op='INDEX RANGE SCAN MY_ORDER_TEST_NDX_1 (cr=3 pr=0 pw=0 time=47 us)'
STAT #2 id=5 cnt=0 pid=2 pos=2 obj=54900 op='TABLE ACCESS FULL MY_SOURCE_TAB (cr=0 pr=0 pw=0 time=0 us)'
=====================
PARSING IN CURSOR #1 len=30 dep=0 uid=64 oct=3 lid=64 tim=101226943872 hv=3007295325 ad='2ae92c70'
select count(*) from to_shrink
END OF STMT
PARSE #1:c=0,e=66,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=101226943864
EXEC #1:c=0,e=105,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=101226950809
WAIT #1: nam='SQL*Net message to client' ela= 8 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=101226952270
FETCH #1:c=0,e=10926,p=0,cr=499,cu=0,mis=0,r=1,dep=0,og=1,tim=101226965517
WAIT #1: nam='SQL*Net message from client' ela= 279 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=101226967554
FETCH #1:c=0,e=5,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=101226969482
WAIT #1: nam='SQL*Net message to client' ela= 8 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=101226971120
*** 2008-03-29 00:37:19.328
WAIT #1: nam='SQL*Net message from client' ela= 12707496 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=101239680105
STAT #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=499 pr=0 pw=0 time=10927 us)'
STAT #1 id=2 cnt=33100 pid=1 pos=1 obj=56876 op='TABLE ACCESS FULL TO_SHRINK (cr=499 pr=0 pw=0 time=99382 us)'
=====================




Can I run tkprof on this partial trace ? Yes, I can. These are the results :


select o.id, o.name from my_order_test o, my_source_tab s
where o.name=s.object_name
and o.id > 57000
order by o.id

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 3 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 3 0 0

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

Rows Row Source Operation
------- ---------------------------------------------------
0 SORT ORDER BY (cr=3 pr=0 pw=0 time=388 us)
0 HASH JOIN (cr=3 pr=0 pw=0 time=358 us)
0 TABLE ACCESS BY INDEX ROWID MY_ORDER_TEST (cr=3 pr=0 pw=0 time=60 us)
0 INDEX RANGE SCAN MY_ORDER_TEST_NDX_1 (cr=3 pr=0 pw=0 time=47 us)(object id 57002)
0 TABLE ACCESS FULL MY_SOURCE_TAB (cr=0 pr=0 pw=0 time=0 us)


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

select count(*)
from
to_shrink


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 2 0.00 0.01 0 499 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.01 0 499 0 1

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 64

Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=499 pr=0 pw=0 time=10927 us)
33100 TABLE ACCESS FULL TO_SHRINK (cr=499 pr=0 pw=0 time=99382 us)


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 2 0.00 0.00
SQL*Net message from client 2 12.70 12.70



There we have it. A tkprof on a "partial" trace file (one that has been sliced out of the full file) -- on a file which doesn't even have proper headers. I took care to ensure that the slice of the trace file does include all the WAIT events and the Row Source Operations.


Here's another slice of the trace file :


PARSING IN CURSOR #1 len=30 dep=0 uid=64 oct=3 lid=64 tim=101226943872 hv=3007295325 ad='2ae92c70'
select count(*) from to_shrink
END OF STMT
PARSE #1:c=0,e=66,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=101226943864
EXEC #1:c=0,e=105,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=101226950809
WAIT #1: nam='SQL*Net message to client' ela= 8 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=101226952270
FETCH #1:c=0,e=10926,p=0,cr=499,cu=0,mis=0,r=1,dep=0,og=1,tim=101226965517
WAIT #1: nam='SQL*Net message from client' ela= 279 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=101226967554
FETCH #1:c=0,e=5,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=101226969482
WAIT #1: nam='SQL*Net message to client' ela= 8 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=101226971120
*** 2008-03-29 00:37:19.328
WAIT #1: nam='SQL*Net message from client' ela= 12707496 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=101239680105
STAT #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=499 pr=0 pw=0 time=10927 us)'
STAT #1 id=2 cnt=33100 pid=1 pos=1 obj=56876 op='TABLE ACCESS FULL TO_SHRINK (cr=499 pr=0 pw=0 time=99382 us)'
=====================
PARSING IN CURSOR #1 len=493 dep=1 uid=0 oct=3 lid=0 tim=101239685660 hv=2584065658 ad='2faf0ddc'
select t.ts#,t.file#,t.block#,nvl(t.bobj#,0),nvl(t.tab#,0),t.intcols,nvl(t.clucols,0),t.audit$,t.flags,t.pctfree$,t.pctused$,t.initrans,t.maxtrans,t.rowcnt,t.blkcnt,t.empcnt,t.avgspc,t.chncnt,t.avgrln,t.analyzetime,t.samplesize,t.cols,t.property,nvl(t.degree,1),nvl(t.instances,1),t.avgspc_flb,t.flbcnt,t.kernelcols,nvl(t.trigflag, 0),nvl(t.spare1,0),nvl(t.spare2,0),t.spare4,t.spare6,ts.cachedblk,ts.cachehit,ts.logicalread from tab$ t, tab_stats$ ts where t.obj#= :1 and t.obj# = ts.obj# (+)
END OF STMT
PARSE #1:c=0,e=29,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=101239685652
EXEC #1:c=0,e=87,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=101239694390
FETCH #1:c=0,e=174,p=0,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=101239696127
STAT #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='NESTED LOOPS OUTER (cr=4 pr=0 pw=0 time=160 us)'
STAT #1 id=2 cnt=1 pid=1 pos=1 obj=4 op='TABLE ACCESS CLUSTER TAB$ (cr=3 pr=0 pw=0 time=114 us)'
STAT #1 id=3 cnt=1 pid=2 pos=1 obj=3 op='INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=0 pw=0 time=33 us)'
STAT #1 id=4 cnt=0 pid=1 pos=2 obj=708 op='TABLE ACCESS BY INDEX ROWID TAB_STATS$ (cr=1 pr=0 pw=0 time=24 us)'
STAT #1 id=5 cnt=0 pid=4 pos=1 obj=709 op='INDEX UNIQUE SCAN I_TAB_STATS$_OBJ# (cr=1 pr=0 pw=0 time=13 us)'
=====================
PARSING IN CURSOR #1 len=789 dep=1 uid=0 oct=3 lid=0 tim=101239706457 hv=3159716790 ad='2faeeabc'
select i.obj#,i.ts#,i.file#,i.block#,i.intcols,i.type#,i.flags,i.property,i.pctfree$,i.initrans,i.maxtrans,i.blevel,i.leafcnt,i.distkey,i.lblkkey,i.dblkkey,i.clufac,i.cols,i.analyzetime,i.samplesize,i.dataobj#,nvl(i.degree,1),nvl(i.instances,1),i.rowcnt,mod(i.pctthres$,256),i.indmethod#,i.trunccnt,nvl(c.unicols,0),nvl(c.deferrable#+c.valid#,0),nvl(i.spare1,i.intcols),i.spare4,i.spare2,i.spare6,decode(i.pctthres$,null,null,mod(trunc(i.pctthres$/256),256)),ist.cachedblk,ist.cachehit,ist.logicalread from ind$ i, ind_stats$ ist, (select enabled, min(cols) unicols,min(to_number(bitand(defer,1))) deferrable#,min(to_number(bitand(defer,4))) valid# from cdef$ where obj#=:1 and enabled > 1 group by enabled) c where i.obj#=c.enabled(+) and i.obj# = ist.obj#(+) and i.bo#=:1 order by i.obj#
END OF STMT
PARSE #1:c=0,e=50,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=101239706448
EXEC #1:c=0,e=144,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=101239714327
FETCH #1:c=0,e=428,p=0,cr=3,cu=0,mis=0,r=0,dep=1,og=4,tim=101239716321
STAT #1 id=1 cnt=0 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=3 pr=0 pw=0 time=474 us)'
STAT #1 id=2 cnt=0 pid=1 pos=1 obj=0 op='HASH JOIN OUTER (cr=3 pr=0 pw=0 time=429 us)'
STAT #1 id=3 cnt=0 pid=2 pos=1 obj=0 op='NESTED LOOPS OUTER (cr=3 pr=0 pw=0 time=91 us)'
STAT #1 id=4 cnt=0 pid=3 pos=1 obj=19 op='TABLE ACCESS CLUSTER IND$ (cr=3 pr=0 pw=0 time=79 us)'
STAT #1 id=5 cnt=1 pid=4 pos=1 obj=3 op='INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=0 pw=0 time=35 us)'
STAT #1 id=6 cnt=0 pid=3 pos=2 obj=710 op='TABLE ACCESS BY INDEX ROWID IND_STATS$ (cr=0 pr=0 pw=0 time=0 us)'
STAT #1 id=7 cnt=0 pid=6 pos=1 obj=711 op='INDEX UNIQUE SCAN I_IND_STATS$_OBJ# (cr=0 pr=0 pw=0 time=0 us)'
STAT #1 id=8 cnt=0 pid=2 pos=2 obj=0 op='VIEW (cr=0 pr=0 pw=0 time=0 us)'
STAT #1 id=9 cnt=0 pid=8 pos=1 obj=0 op='SORT GROUP BY (cr=0 pr=0 pw=0 time=0 us)'
STAT #1 id=10 cnt=0 pid=9 pos=1 obj=31 op='TABLE ACCESS BY INDEX ROWID CDEF$ (cr=0 pr=0 pw=0 time=0 us)'
STAT #1 id=11 cnt=0 pid=10 pos=1 obj=51 op='INDEX RANGE SCAN I_CDEF2 (cr=0 pr=0 pw=0 time=0 us)'
=====================
PARSING IN CURSOR #1 len=348 dep=1 uid=0 oct=3 lid=0 tim=101239734792 hv=2512561537 ad='2fafea98'
select name,intcol#,segcol#,type#,length,nvl(precision#,0),decode(type#,2,nvl(scale,-127/*MAXSB1MINAL*/),178,scale,179,scale,180,scale,181,scale,182,scale,183,scale,231,scale,0),null$,fixedstorage,nvl(deflength,0),default$,rowid,col#,property, nvl(charsetid,0),nvl(charsetform,0),spare1,spare2,nvl(spare3,0) from col$ where obj#=:1 order by intcol#
END OF STMT
PARSE #1:c=0,e=53,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=101239734783
EXEC #1:c=0,e=110,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=101239742906
FETCH #1:c=0,e=169,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,tim=101239744762
FETCH #1:c=0,e=30,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=101239746407
FETCH #1:c=0,e=29,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=101239747966
FETCH #1:c=0,e=29,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=101239750079
STAT #1 id=1 cnt=3 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=3 pr=0 pw=0 time=176 us)'
STAT #1 id=2 cnt=3 pid=1 pos=1 obj=21 op='TABLE ACCESS CLUSTER COL$ (cr=3 pr=0 pw=0 time=92 us)'
STAT #1 id=3 cnt=1 pid=2 pos=1 obj=3 op='INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=0 pw=0 time=37 us)'
=====================
PARSING IN CURSOR #1 len=169 dep=1 uid=0 oct=3 lid=0 tim=101239756557 hv=1173719687 ad='2fae8e88'
select col#, grantee#, privilege#,max(mod(nvl(option$,0),2)) from objauth$ where obj#=:1 and col# is not null group by privilege#, col#, grantee# order by col#, grantee#
END OF STMT
PARSE #1:c=0,e=52,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=101239756548
EXEC #1:c=0,e=134,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=101239762520
FETCH #1:c=0,e=70,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=101239762642
STAT #1 id=1 cnt=0 pid=0 pos=1 obj=0 op='SORT GROUP BY (cr=2 pr=0 pw=0 time=108 us)'
STAT #1 id=2 cnt=0 pid=1 pos=1 obj=57 op='TABLE ACCESS BY INDEX ROWID OBJAUTH$ (cr=2 pr=0 pw=0 time=61 us)'
STAT #1 id=3 cnt=0 pid=2 pos=1 obj=103 op='INDEX RANGE SCAN I_OBJAUTH1 (cr=2 pr=0 pw=0 time=45 us)'
=====================
PARSING IN CURSOR #1 len=151 dep=1 uid=0 oct=3 lid=0 tim=101239762907 hv=4139184264 ad='2fae8560'
select grantee#,privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))from objauth$ where obj#=:1 group by grantee#,privilege#,nvl(col#,0) order by grantee#
END OF STMT
PARSE #1:c=0,e=46,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=101239762902
EXEC #1:c=0,e=52,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=101239763127
FETCH #1:c=0,e=29,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=101239763201
STAT #1 id=1 cnt=0 pid=0 pos=1 obj=0 op='SORT GROUP BY (cr=2 pr=0 pw=0 time=54 us)'
STAT #1 id=2 cnt=0 pid=1 pos=1 obj=57 op='TABLE ACCESS BY INDEX ROWID OBJAUTH$ (cr=2 pr=0 pw=0 time=25 us)'
STAT #1 id=3 cnt=0 pid=2 pos=1 obj=103 op='INDEX RANGE SCAN I_OBJAUTH1 (cr=2 pr=0 pw=0 time=16 us)'
=====================
PARSING IN CURSOR #1 len=69 dep=1 uid=0 oct=3 lid=0 tim=101239763420 hv=1471956217 ad='2fae9868'
select con#,obj#,rcon#,enabled,nvl(defer,0) from cdef$ where robj#=:1
END OF STMT
PARSE #1:c=0,e=23,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=101239763415
EXEC #1:c=0,e=30,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=101239763610
FETCH #1:c=0,e=22,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,tim=101239763677
STAT #1 id=1 cnt=0 pid=0 pos=1 obj=31 op='TABLE ACCESS BY INDEX ROWID CDEF$ (cr=1 pr=0 pw=0 time=29 us)'
STAT #1 id=2 cnt=0 pid=1 pos=1 obj=52 op='INDEX RANGE SCAN I_CDEF3 (cr=1 pr=0 pw=0 time=19 us)'
=====================
PARSING IN CURSOR #1 len=146 dep=1 uid=0 oct=3 lid=0 tim=101239763835 hv=2107929772 ad='2faf4cb8'
select con#,type#,condlength,intcols,robj#,rcon#,match#,refact,nvl(enabled,0),rowid,cols,nvl(defer,0),mtime,nvl(spare1,0) from cdef$ where obj#=:1
END OF STMT
PARSE #1:c=0,e=17,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=101239763830
EXEC #1:c=0,e=52,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=101239764132
FETCH #1:c=0,e=22,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=101239764200
STAT #1 id=1 cnt=0 pid=0 pos=1 obj=31 op='TABLE ACCESS BY INDEX ROWID CDEF$ (cr=2 pr=0 pw=0 time=29 us)'
STAT #1 id=2 cnt=0 pid=1 pos=1 obj=51 op='INDEX RANGE SCAN I_CDEF2 (cr=2 pr=0 pw=0 time=18 us)'
=====================
PARSING IN CURSOR #2 len=115 dep=0 uid=64 oct=3 lid=64 tim=101239765477 hv=1396900901 ad='2ae90eec'
select o.id, o.name from my_order_test o, my_source_tab s
where o.name=s.object_name
and o.id > 57000
order by o.id
END OF STMT
PARSE #2:c=78125,e=80402,p=0,cr=17,cu=0,mis=1,r=0,dep=0,og=1,tim=101239765469
EXEC #2:c=0,e=77,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=101239765811
WAIT #2: nam='SQL*Net message to client' ela= 6 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=101239765937
FETCH #2:c=31250,e=42294,p=0,cr=3421,cu=0,mis=0,r=0,dep=0,og=1,tim=101239808289
WAIT #2: nam='SQL*Net message from client' ela= 5281 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=101239813784
STAT #2 id=1 cnt=0 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=3421 pr=0 pw=0 time=42304 us)'
STAT #2 id=2 cnt=0 pid=1 pos=1 obj=0 op='HASH JOIN (cr=3421 pr=0 pw=0 time=42278 us)'
STAT #2 id=3 cnt=0 pid=2 pos=1 obj=56926 op='TABLE ACCESS FULL MY_ORDER_TEST (cr=3421 pr=0 pw=0 time=41969 us)'
STAT #2 id=4 cnt=0 pid=2 pos=2 obj=54900 op='TABLE ACCESS FULL MY_SOURCE_TAB (cr=0 pr=0 pw=0 time=0 us)'
=====================
PARSING IN CURSOR #1 len=30 dep=0 uid=64 oct=3 lid=64 tim=101239814146 hv=3007295325 ad='2ae92c70'
select count(*) from to_shrink
END OF STMT
PARSE #1:c=0,e=30,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=101239814141
EXEC #1:c=0,e=61,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=101239814346
WAIT #1: nam='SQL*Net message to client' ela= 4 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=101239814403
FETCH #1:c=0,e=8862,p=0,cr=499,cu=0,mis=0,r=1,dep=0,og=1,tim=101239823406
WAIT #1: nam='SQL*Net message from client' ela= 257 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=101239823870
FETCH #1:c=0,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=101239823937
WAIT #1: nam='SQL*Net message to client' ela= 2 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=101239823983
*** 2008-03-29 00:37:29.718
WAIT #1: nam='SQL*Net message from client' ela= 10247440 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=101250071475
XCTEND rlbk=0, rd_only=1
STAT #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=499 pr=0 pw=0 time=8865 us)'
STAT #1 id=2 cnt=33100 pid=1 pos=1 obj=56876 op='TABLE ACCESS FULL TO_SHRINK (cr=499 pr=0 pw=0 time=99360 us)'




I have taken the first execution of the "select count(*) from to_shrink;" in both "slices" or pieces of the trace file.

Here's the tkprof of the second slice. In this tkprof, I can see the different Execution Plan (Rows Source Operations) for the SQL joining MY_ORDER_TEST with MY_SOURCE_TAB (because an index on MY_ORDER_TEST was dropped) :


select count(*)
from
to_shrink


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 4 0.00 0.01 0 998 0 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 8 0.00 0.02 0 998 0 2

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 64

Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=499 pr=0 pw=0 time=10927 us)
33100 TABLE ACCESS FULL TO_SHRINK (cr=499 pr=0 pw=0 time=99382 us)


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 4 0.00 0.00
SQL*Net message from client 4 12.70 22.95
********************************************************************************

select o.id, o.name from my_order_test o, my_source_tab s
where o.name=s.object_name
and o.id > 57000
order by o.id

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.07 0.07 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.03 0.04 0 3421 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.10 0.12 0 3421 0 0

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

Rows Row Source Operation
------- ---------------------------------------------------
0 SORT ORDER BY (cr=3421 pr=0 pw=0 time=42304 us)
0 HASH JOIN (cr=3421 pr=0 pw=0 time=42278 us)
0 TABLE ACCESS FULL MY_ORDER_TEST (cr=3421 pr=0 pw=0 time=41969 us)
0 TABLE ACCESS FULL MY_SOURCE_TAB (cr=0 pr=0 pw=0 time=0 us)


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





This is where I see the balance 3,421 block gets for the same SQL statement, but a different execution plan.

2 comments:

Timur Ahmadeev said...

Hello, Hemant.
Why don't you use aggregate=no option of the tkprof? It's also usable for such cases, though size of the resulted file will be much more bigger in size.

Hemant K Chitale said...

Yes, I could use aggregate=no. Thanks.

However, if I have a large(ish) trace file, I'd still want to be able to "slice" it and run seperate tkprofs.

Aggregated by orafaq.com

Aggregated by orafaq.com
This blog is being aggregated by orafaq.com

Top 50 Oracle SQL Blogs 2016

Top 50 Oracle SQL Blogs 2016
Top 50 Oracle SQL Blogs 2016