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:
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.
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.
Post a Comment