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.

tkprof on partial trace files

There may be occassions when you need to or wish to run a tkprof on only a portion of a trace file (a fragment of the trace file or a partial trace file).

Cases where I've used this approach are similar to these examples :
1. Tracing was executed for an application server process running for 30minutes, probably running the same 40 SQL statements 20times (a total of 800 execution) in those 30minutes. Assuming that I am interested in 1 particular SQL statement that took 240seconds for 1 of the 20executions (maybe the fifth execution), 180seconds for another (possibly the eighteenth execution) and 5seconds each for all other 18executions.
If I were to run a tkprof on the whole trace file, it would show me that the SQL was executed 20 times but would show me Row Source Operations for *only 1* of those 20 executions. That 1 execution might be the case where it fetched 200 rows in 5seconds.
Oracle might very well have used the same execution plan for all 20 executions but, because of the nature of the underlying data, it might be suboptimal for those 2 occurrences which took 240seconds and 180seconds each. Quite possible, right ?
tkprof's listing of Row Source Operations does not show me all 20 execution.
However, the raw trace file would show 20 sets of STAT# lines where I can read the Row Source Operations from. {This is assuming that the cursor is closed after every execution. If the cursor doesn't get closed, STAT# lines are not placed in the trace file}.
Such a case would be where tkprof is "lying" to me -- but it is really only providing me partial data. {Although it still says that the summed execution time for the 20executions was 410seconds (240+180+18*5), the Row Source Operations details are for a 5seconds execution. The minimum time was 5seconds, the maximum was 240seconds. This (min/max execution time) information, too, is not available in tkprof.

2. During the course of the execution of the application server program, a developer drops an index on a key table accessed by the one (of the 30 !) SQL statement that I am interested in (he could have dropped the index when another SQL was being executed).
Say, he dropped the index after the fifth execution. The next 15 executions would have a different Execution Plan from the first 5 executions. Yet, tkprof will NOT tell me that there were at least 2 different Execution Plans. I can discern that from the "Misses in library cache" information but the Row Source Operation section would show me only 1 of the (at least 2 different) Execution Plans. So, once again, tkprof is "lying" in that it is not presenting the complete information.

What would I do in such cases ? I would split up the trace file into, maybe, 20 different pieces and run a tkprof on each piece. (Assuming that the cursor was closed each of the 20 times), I can see all 20 sets of Row Source Operation details now ! For the first case, I can see in one of the 20 trace files that the SQL took 240seconds and Row Source Operations would show me where (which index scan , table fetch, join operation etc) it spent the most time !

This leads to the question : How can I split the trace file ? Don't I have to maintain the "consistency" of the trace file ? Shouldn't the header information be repeated in all 20 pieces ?

NO, I can slice the trace file (horizontally of course, not vertically) at any point and still run tkprof. If, of course, I slice it incorrectly such that the WAIT events and/or Row Source Operations for an SQL execution are not in the same "slice" (piece), tkprof cannot tell me the correct (or would actually present incorrect) Wait times / Row Source operations. However, if I slice the file correctly (forget the trace file header, it is not important to me), I can get seperate tkprofs.

Backup the Online Redo Logs ?

On a recent oracle forum dicussion which started of with the title "Multiplex redo log files?" but really with the question "Is it a normal operation to backup redo log files as well ?", I put in a response to the "normal" assertion to "never backup redo logs".

There's probably no documentation that "says to include online redo logs as part of a backup".
However, there are situations where you _can_ (or even would want to) include your redo logs in a backup. Note that I say "a backup", not "backups". A specific, adhoc, backup may include redo logs.

1. I take a cold backup of a database and restore it to another server. I do not wish to do a RESETLOGS (why, I ask "do I HAVE to resetlogs ?"). Then, I include my redo logs in my cold backup and restore.

2. I am testing backup and recovery scenarios. I take a cold backup of the whole database as a "reference point" in all my various recovery tests.

3. I am attempting a recovery of a production database to verify data at different points in time. I know that I might have to also do a resetlogs in between, change the incarnation id, maybe even change the db_name etc. I want to be able to revert to any restored image during the few rounds of restore-and-verify-data. Those intermediate backups would well be cold backups with redo logs (after resetlogs ?)

4. I am remotely advising a DBA on recovery of a crashed database. I cannot be sure that he has verified all the archivelogs, got the current log sequence numbers etc. I know that it is likely that one or more of the online redo logs hadn't yet been archivedand I would be able to "simulate" them as archived logs during the recovery -- but only if I do ensure that the redo logs are backed up.

5. The last one or two archivelogs had not got included in the tape backup. However, since I know that the database has 4 or 5 or 6 online redo logs, those last two are still available "on-disk" in the form of "online" redo logs (which might very well be raw devices, just to make things more complicated), which haven't been "lost" in the filesystem crash.


Bottom Line : As a "general" rule, it is not necessary to backup online redo logs.As a "general" piece of advise, it _can_ be dangerous to blindly backup online redologs, even in cold backups.However, there can be *specific* cases where I know I would want to backup the online redo logs.
Remember that "online redo logs" doesn't mean exactly the same as "CURRENT" or "ACTIVE".