Interpreting Raw Sql Trace File

SQL_TRACE is the main method for collecting SQL Execution information in Oracle. It records a wide range of information and statistics that can be used to tune SQL operations. The sql trace file contains a great deal of information . Each cursor that is opened after tracing has been enabled will be recorded in the trace file. 

The raw trace file mostly contains the cursor number . Eg, PARSING IN CURSOR #3 . EXECutes, FETCHes and WAITs are recorded against a cursor. The information applies to the most recently parsed statement within that cursor . Firstly,  let's have a look on "Wait Events"  . 

WAIT #6: nam='db file sequential read' ela= 8458 file#=110 block#=63682 blocks=1 obj#=221 tim=506028963546

WAIT        = An event that we waited for.
nam           = What was being waited for . The wait events here are the same as are seen in view V$SESSION_WAIT .
ela             = Elapsed time for the operation.(microseconds)
p1 = P1 for the given wait event.
p2 = P2 for the given wait event.
p3     = P3 for the given wait event.

Example No. 1 : WAIT #6: nam='db file sequential read' ela= 8458 file#=110 block#=63682 blocks=1 obj#=221 tim=506028963546 

The above line can be translated as  : Completed waiting under CURSOR no 6  for "db file sequential read" . We waited 8458 microseconds i.e. approx. 8.5 milliseconds .For a read of:  File 110, start block 63682, for 1 Oracle block of Object number 221. Timestamp was 506028963546 . 

Example no.2 : WAIT #1: nam='library cache: mutex X' ela= 814 idn=3606132107 value=3302829850624 where=4 obj#=-1 tim=995364327604

The above line can be translated as : Completed WAITing under CURSOR no 1 for "library cache: mutex X" .We waited 814 microseconds i.e. approx. 0.8 milliseconds .To get an eXclusive library cache latch with  Identifier 3606132107 value 3302829850624 location 4 . It was not associated with any particular object (obj#=-1) Timestamp 995364327604.

The trace file also show the processing of the sql statements . Oracle processes SQL statements as follow :
Stage 1: Create a Cursor
Stage 2: Parse the Statement
Stage 3: Describe Results
Stage 4: Defining Output
Stage 5: Bind Any Variables
Stage 6: Execute the Statement
Stage 7: Parallelize the Statement
Stage 8: Fetch Rows of a Query Result
Stage 9: Close the Cursor
Now let's  move to another important term PARSING IN CURSOR #n . EXECutes, FETCHes and WAITs are recorded against a cursor. The information applies to the most recently parsed statement within that cursor.

PARSING IN CURSOR# : 

Cursor :  In order for Oracle to process an SQL statement, it needs to create an area of memory known as the context area; this will have the information needed to process the statement. This information includes the number of rows processed by the statement, a pointer to the parsed representa-tion of the statement (parsing an SQL statement is the process whereby information is transferred to the server, at which point the SQL statement is evaluated as being valid).

A cursor is a handle, or pointer, to the context area. Through the cursor, a PL/SQL program can control the context area and what happens to it as the statement is processed. Two important features about the cursor are

1.)  Cursors allow you to fetch and process rows returned by a SE-LECT statement, one row at a time.

2.)  A cursor is named so that it can be referenced.

Parsing : Oracle Parsing is the first step in processing of any database statement . PARSE record is accompanied by the cursor number. Let's have a look on "Parsing in Cursor" of a particular trace file .

PARSING IN CURSOR #2 len=92 dep=0 uid=0 oct=3 lid=0 tim=277930332201 hv=1039576264 ad='15d51e60' sqlid='dsz47ssyzdb68'

select p.PID,p.SPID,s.SID from v$process p,v$session s where s.paddr = p.addr and s.sid = 12

END OF STMT

PARSE#2:c=31250,e=19173,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=836746634,tim=27930332198

EXEC #2:c=0,e=86,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=836746634,tim=77930335666

WAIT #2: nam='SQL*Net message to client' ela= 10 driver id=1413697536 #bytes=1 p3=0 obj#=116 tim=77930335778

FETCH #2:c=0,e=805,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=836746634,tim=77930336684

WAIT #2: nam='SQL*Net message from client' ela= 363 driver id=1413697536 #bytes=1 p3=0 obj#=116 tim=77930337227

FETCH #2:c=0,e=31,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=836746634,tim=77930337421

STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='NESTED LOOPS  (cr=0 pr=0 pw=0 time=0 us cost=0 size=152 card=1)'

STAT #2 id=2 cnt=27 pid=1 pos=1 obj=0 op='MERGE JOIN CARTESIAN (cr=0 pr=0 pw=0 time=156 us cost=0 size=96 card=1)'

STAT #2 id=3 cnt=1 pid=2 pos=1 obj=0 op='NESTED LOOPS  (cr=0 pr=0 pw=0 time=0 us cost=0 size=39 card=1)'

STAT #2 id=4 cnt=1 pid=3 pos=1 obj=0 op='FIXED TABLE FIXED INDEX X$KSLWT (ind:1) (cr=0 pr=0 pw=0 time=0 us cost=0 size=26 card=1)'

STAT #2 id=5 cnt=1 pid=3 pos=2 obj=0 op='FIXED TABLE FIXED INDEX X$KSLED (ind:2) (cr=0 pr=0 pw=0 time=0 us cost=0 size=13 card=1)'

STAT #2 id=6 cnt=27 pid=2 pos=2 obj=0 op='BUFFER SORT (cr=0 pr=0 pw=0 time=78 us cost=0 size=57 card=1)'

STAT #2 id=7 cnt=27 pid=6 pos=1 obj=0 op='FIXED TABLE FULL X$KSUPR (cr=0 pr=0 pw=0 time=130 us cost=0 size=57 card=1)'

STAT #2 id=8 cnt=1 pid=1 pos=2 obj=0 op='FIXED TABLE FIXED INDEX X$KSUSE (ind:1) (cr=0 pr=0 pw=0 time=0 us cost=0 size=56 card=1)'

WAIT #2: nam='SQL*Net message to client' ela= 7 driver id=1413697536 #bytes=1 p3=0 obj#=116 tim=77930338248

*** 2012-05-19 15:07:22.843

WAIT #2: nam='SQL*Net message from client' ela= 38291082 driver id=1413697536 #bytes=1 p3=0 obj#=116 tim=77968629417

CLOSE #2:c=0,e=30,dep=0,type=0,tim=77968629737

len     = the number of characters in the SQL statement
dep   = tells the application/trigger depth at which the SQL statement was executed. dep=0 indicates that it was executed by the client application. dep=1 indicates that the SQL statement was executed by a trigger, the Oracle optimizer, or a space management call. dep=2 indicates that the SQL statement was called from a trigger, dep=3 indicates that the SQL statement was called from a trigger that was called from a trigger.
uid     = Schema id under which SQL was parsed.
oct = Oracle command type.
lid = Privilege user id
tim    = Timestamp.
hv = Hash id.
ad = SQLTEXT address

PARSE #3:  c=15625,  e=177782,  p=2,  cr=3,  cu=0,  mis=1,  r=0,  dep=0,  og=1,  plh=272002086,

tim=276565143470

c      = CPU time (microseconds rounded to centiseconds granularity on 9i & above)
e  = Elapsed time (centiseconds prior to 9i, microseconds thereafter)
p  = Number of physical reads.
cr  = Number of buffers retrieved for CR reads.(Consistent reads)
cu    =Number of buffers retrieved in current mode.
mis  = Cursor missed in the cache.
r  = Number of rows processed.
dep = Recursive call depth (0 = user SQL, >0 = recursive).
og = Optimizer goal: 1=All_Rows, 2=First_Rows, 3=Rule, 4=Choose


From the above Parse line it is very clear that the total time taken in parsing the statement is  0.177 sec and the no. of physical reads done are 2 .

Bind Variables :  If the SQL statement does reference bind variables, then the following  SQL statement shown in the cursor can locate a section of text associated with each bind variable. For each bind variable there are a number of attributes listed.  The following are the ones we are interested in here:

mxl      =  the maximum length - ie. the maximum number of bytes occupied by the variable. Eg. dty=2 and mxl=22 denotes a NUMBER(22) column.
scl       = the scale (for NUMBER columns)
pre      = the precision (for NUMBER columns)
value  = the value of the bind variable
dty      = the datatype.  Typical values are:
1       VARCHAR2 or NVARCHAR2
2       NUMBER
8       LONG
11     ROWID
12     DATE
23     RAW
24     LONG RAW
96     CHAR
112   CLOB or NCLOB
113   BLOB
114   BFILE

EXEC :  Execute a pre-parsed statement. At this point, Oracle has all necessary information and resources, so the statement is executed. For example

EXEC #2:c=0,e=225,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3684871272,tim=282618239403

Fetch : Fetch rows from a cursor . For example
FETCH #4:c=0,e=8864,p=1,cr=26,cu=0,mis=0,r=1,dep=0,og=1,plh=3564694750,tim=282618267037


STAT :  Lines report explain plan statistics for the numbered [CURSOR]. These let us know the 'run time' explain plan. For example
STAT #1 id=1 cnt=7 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=0 pr=0 pw=0 time=0 us cost=2 size=2128 card=1)'

id       = Line of the explain plan which the row count applies to (starts at line 1).  This is effectively the row source row count for all row sources in the execution tree
cnt =  Number of rows for this row source.
pid  =  Parent id of this row source.
pos   =  Position in explain plan.
obj     =  Object id of row source (if this is a base object).
op='...'   The row source access operation


XCTEND  A transaction end marker. For example  XCTEND rlbk=0, rd_only=1, tim=282636050491
rlbk           =1   if a rollback was performed, 0 if no rollback (commit).
rd_only      =1   if transaction was read only, 0 if changes occurred.


CLOSE  cursor is closed .for example CLOSE #4:c=0,e=32,dep=0,type=0,tim=282636050688
c            = CPU time (microseconds rounded to centiseconds granularity on 9i and above)
e           = Elapsed time (centiseconds prior to 9i, microseconds thereafter)
dep       = Recursive depth of the cursor
type     = Type of close operation

Note : Timestamp are used to determine the time between any 2 operations.
Reference : Metalink [ID 39817.1]



Enjoy    :-)