Database Reference
In-Depth Information
As mentioned, the preceding sample is generated by a tool named TKPROF. It's not the output generated by SQL
trace. In fact, SQL trace outputs text files, storing raw information about the interactions between components. Here's
an excerpt of the trace file related to the previous sample. Generally, for each call or wait, there's at least one line in the
trace file:
...
...
PARSING IN CURSOR
#140105537106328 len=139 dep=1 uid=77 oct=3 lid=93 tim=1344867866442114
hv=2959931450 ad='706df490' sqlid='arc3zqqs6ty1u'
SELECT CUST_ID, EXTRACT(YEAR FROM TIME_ID), SUM(AMOUNT_SOLD) FROM SALES WHERE CHANNEL_ID = :B1
GROUP BY CUST_ID, EXTRACT(YEAR FROM TIME_ID)
END OF STMT
PARSE
#140105537106328:c=1999,e=1397,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=0, tim=1344867866442113
BINDS
#140105537106328:
Bind#0
oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1206001 frm=00 csi=00 siz=24 off=0
kxsbbbfp=7f6cdcc6c6e0 bln=22 avl=02 flg=05
value=3
EXEC
#140105537106328:c=7000,e=7226,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=3604305554,
tim=1344867866449493
WAIT
#140105537106328: nam='Disk file operations I/O' ela= 45 FileOperation=2 fileno=4 filetype=2
obj#=69232 tim=1344867866450319
WAIT
#140105537106328: nam='db file sequential read' ela= 59 file#=4 block#=5009 blocks=1 obj#=69232
tim=1344867866450423
...
...
FETCH
#140105537106328:c=0,e=116,p=0,cr=0,cu=0,mis=0,r=48,dep=1,og=1,plh=3604305554,
tim=1344867867730523
STAT
#140105537106328 id=1 cnt=16348 pid=0 pos=1 obj=0 op='HASH GROUP BY (cr=1781 pr=3472 pw=1699
time=1206229 us cost=9220 size=4823931 card=229711)'
STAT
#140105537106328 id=2 cnt=540328 pid=1 pos=1 obj=0 op='PARTITION RANGE ALL PARTITION: 1 28
(cr=1781 pr=1773 pw=0 time=340163 us cost=1414 size=4823931 card=229711)'
STAT
#140105537106328 id=3 cnt=540328 pid=2 pos=1 obj=69227 op='TABLE ACCESS FULL SALES PARTITION: 1
28 (cr=1781 pr=1773 pw=0 time=280407 us cost=1414 size=4823931 card=229711)'
CLOSE
#140105537106328:c=0,e=1,dep=1,type=3,tim=1344867867730655
...
...
In the previous excerpt, some tokens describing the kind of information provided are highlighted in bold:
PARSING IN CURSOR
and
END OF STMT
enclose the text of the SQL statement.
•
PARSE
,
EXEC
,
FETCH
, and
CLOSE
for parse, execute, fetch, and close calls, respectively.
•
BINDS
for the definition and value of bind variables.
•
WAIT
for the wait events that occurred during the processing.
•
STAT
for the execution plans that occurred and associated statistics.
•
You can find a short description of the trace files' format in the Oracle Support note
Interpreting Raw SQL_TRACE
output
(39817.1). If you're interested in a detailed description and discussion of this topic, Millsap's book
The Method
