Reading the Oracle 10046 Trace File sections, parse, execute, fetch & wait

Inside the Oracle 10046 Trace File Output

The 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. Here is a sample excerpt from a trace file:

=====================

PARSING IN CURSOR #2 len=79 dep=0 uid=73 oct=3 lid=73 tim=259898785365 hv=4060294543 ad='1cd62f00'

SELECT a.emp_first_name, b.job_name

FROM emp a, job b

WHERE a.job_key=b.job_key

END OF STMT

PARSE #2:c=0,e=154,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=259898785352

BINDS #2:

EXEC #2:c=0,e=12571,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=259898883135

WAIT #2: nam='SQL*Net message to client' ela= 10 p1=1111838976 p2=1 p3=0

FETCH #2:c=0,e=854,p=0,cr=14,cu=0,mis=0,r=1,dep=0,og=1,tim=259898908178

WAIT #2: nam='SQL*Net message from client' ela= 2120 p1=1111838976 p2=1 p3=0

WAIT #2: nam='SQL*Net message to client' ela= 6 p1=1111838976 p2=1 p3=0

FETCH #2:c=0,e=12470,p=0,cr=1,cu=0,mis=0,r=9,dep=0,og=1,tim=259898947719

WAIT #2: nam='SQL*Net message from client' ela= 1353028 p1=1111838976 p2=1 p3=0

XCTEND rlbk=0, rd_only=1

STAT #2 id=1 cnt=10 pid=0 pos=1 obj=0 op='HASH JOIN (cr=15 pr=0 pw=0 time=850 us)'

STAT #2 id=2 cnt=4 pid=1 pos=1 obj=55218 op='TABLE ACCESS FULL OBJ#(55218) (cr=7 pr=0 pw=0 time=168 us)'

STAT #2 id=3 cnt=10 pid=1 pos=2 obj=55217 op='TABLE ACCESS FULL OBJ#(55217) (cr=8 pr=0 pw=0 time=60 us)'

Let’s break down this trace file into its constituent pieces:

Parse Phase of a 10046 Oracle trace

In this section of the trace file, we find the SQL statement and the parse record associated with the parse statement. My comments are in bold face:

This line provides information on the cursor itself. Here we see the length of the cursor (len=79), the user id of the person parsing the cursor (uid=73), the time the parse began (tim=) and the SQL address of the cursor (ad=). As you will see shortly, we can reference the ad= line to v$sqlarea and get the text of this cursor.



=====================

PARSING IN CURSOR #2 len=79 dep=0 uid=73 oct=3 lid=73 tim=259898785365 hv=4060294543 ad='1cd62f00'

This is the SQL statement itself. Note that terminator, END OF STMT.

SELECT a.emp_first_name, b.job_name

FROM emp a, job b

WHERE a.job_key=b.job_key

END OF STMT

This is the actual parse record. Note that many of the variables documented in this comment are reused in the execute and fetch records. The variables are:

C= cpu time, e=elapsed time, p=number of database blocks read, cr=number of consistent mode blocks read. cu=number of current mode blocks read, mis=number of library cache misses, r=number of rows, og=optimizer goal (1=all_rows, 2=first_rows, 3=rule and 4=choose). Also note that the cursor number is #2. Each cursor will be assigned its own number. Cursor numbers can be reused, so be careful about that!

PARSE #2:c=0,e=154,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=259898785352

Notice that the PARSE record is accompanied by the cursor number (#2 in this case).

Execute Phase of a 10046 Oracle trace

First of all, just in case this statement had bind variables, we have enabled tracing with a level 12, so Oracle will capture bind variable information for us. The bind variables will show up in the trace file at this point. Since we are not using bind variables, we move onto the execution (EXEC) phase which is represented by this line:

EXEC #2:c=0,e=12571,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=259898883135

Fetch Phase of a 10046 Oracle trace

Next, as all Oracle DBA’s know, is the fetch phase. You might have noticed the WAIT record before the fetch; we will get to that next. Here is the fetch record. Notice that the variables listed are the same as the parse and execute records (though, of course, some values may be different).

FETCH #2:c=0,e=854,p=0,cr=14,cu=0,mis=0,r=1,dep=0,og=1,tim=259898908178

Those Evil Wait events in the 10046 trace file

The wait events are interspersed throughout the 10046 trace file.

WAIT #2: nam='SQL*Net message to client' ela= 10 p1=1111838976 p2=1 p3=0

In this wait record, we see that our wait event (nam) is SQL*Net message to client. These wait events are the same wait events you will find in the database in the v$ views like v$session_wait or v$event_name.

The elapsed time (ela) is in microseconds since we are on Oracle Database 10g, so this wait was a whole 10 microseconds. Nothing to worry about (1 second = 1,000,000 micro-seconds). The P1, P2 and P3 variables are specific to each event.

Here are some other examples of wait events you might see:

WAIT #7: nam='db file scattered read' ela= 1046 p1=10 p2=166987 p3=2

WAIT #7: nam='db file sequential read' ela= 509 p1=10 p2=166994 p3=1

WAIT #7: nam='buffer busy waits' ela= 26 p1=2 p2=1341 p3=231

WAIT #13: nam='latch free' ela= 0 p1=-2147427600 p2=103 p3=0

WAIT #15: nam='log buffer space' ela= 4 p1=0 p2=0 p3=0

WAIT #38: nam='file open' ela= 0 p1=0 p2=0 p3=0

Other Oracle trace records

Other records appear in 10046 trace files. For example, the execution plan of the statement executed is displayed with a series of STAT records as seen in the overall 10046 trace file we listed earlier in this paper.