when tkprof goes wrong (limitations and mistakes of tkprof)
Tkprof is the utility from Oracle used for analyzing of extended SQL trace files.
It's fast and it seems to be available on every platform where Oracle exists.
No matter whether you are DBA or developer it'll be good for you to be
familiar with tkprof.
But this article isn't about tkprof (tahiti.oracle.com has enough info for this utility) but, contrary, about it's limitations and mistakes (fortunately, a few). Here they are:
1. tkprof does not account for row source operations in stat lines
Look into the raw trace (from real session):
===================== PARSING IN CURSOR #1 len=24 dep=0 uid=47 oct=3 lid=47 tim=1101455068955490 hv=2343063137 ad='3a9621a4' select sysdate from dual END OF STMT PARSE #1:c=0,e=120,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1101455068955475 EXEC #1:c=0,e=92,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1101455068955678 FETCH #1:c=0,e=85,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1101455068955890 STAT #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL (cr=0 pr=0 pw=0 time=57 us)' ===================== PARSING IN CURSOR #1 len=24 dep=0 uid=47 oct=3 lid=47 tim=1101455068957109 hv=2343063137 ad='3a9621a4' select sysdate from dual END OF STMT PARSE #1:c=0,e=42,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1101455068957093 EXEC #1:c=0,e=76,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1101455068957279 FETCH #1:c=0,e=77,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1101455068957459 STAT #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL (cr=0 pr=0 pw=0 time=50 us)'
Pay attention to the couple of 'STAT' lines. First 'STAT' has 'time=57' and the second 'STAT' has 'time=50'.
Here's the tkprof report for this trace:
Rows Row Source Operation
------- ---------------------------------------------------
1 FAST DUAL (cr=0 pr=0 pw=0 time=57 us)
Notice that 'time=57'? Tkprof just get the first 'STAT' line and simply ignored the second. And in this report number of rows equal to 1. But raw trace reports that we fetched twice.
And here's, for comparision, OraSRP' report:
Rows Row Source Operation [Object Id]
-------- --------------------------------
2 FAST DUAL (cr=0 pr=0 pw=0 time=107 us)
OraSRP correctly summarizes two time values (50 and 57) and displays correct time as well as number of rows.
2. tkprof take into account only the first plan
Look into the trace (this time not so real as in previous case):
===================== PARSING IN CURSOR #1 len=24 dep=0 uid=47 oct=3 lid=47 tim=1101455068955490 hv=2343063137 ad='3a9621a4' select sysdate from dual END OF STMT PARSE #1:c=0,e=120,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1101455068955475 EXEC #1:c=0,e=92,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1101455068955678 FETCH #1:c=0,e=85,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1101455068955890 STAT #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL (cr=0 pr=0 pw=0 time=57 us)' ===================== PARSING IN CURSOR #1 len=24 dep=0 uid=47 oct=3 lid=47 tim=1101455068957109 hv=2343063137 ad='3a9621a4' select sysdate from dual END OF STMT PARSE #1:c=0,e=42,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1101455068957093 EXEC #1:c=0,e=76,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1101455068957279 FETCH #1:c=0,e=77,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1101455068957459 STAT #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='SUPER FAST DUAL (cr=0 pr=0 pw=0 time=50 us)'
Different plans for one statement is definitely not a common situation but
this happens from time to time.
Tkprof's report is the same:
Rows Row Source Operation
------- ---------------------------------------------------
1 FAST DUAL (cr=0 pr=0 pw=0 time=57 us)
OraSRP is more intelligent in that case -- it shows both plans:
Statement Plans
Rows Row Source Operation [Object Id]
-------- --------------------------------
1 FAST DUAL (cr=0 pr=0 pw=0 time=57 us)
Rows Row Source Operation [Object Id]
-------- --------------------------------
1 SUPER FAST DUAL (cr=0 pr=0 pw=0 time=50 us)