| |
 |
|
Reading the Oracle 10046 Trace File sections, parse, execute,
fetch & wait
Oracle Tips by
Robert Freeman |
Note: Here are related
Oracle 10046 trace file notes:
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.
Click here
to read next section
Click here
to read previous section
 |
If you like Oracle tuning, see the book "Oracle
Tuning: The Definitive Reference", with 950 pages of tuning tips and
scripts.
You can buy it direct from the publisher for 30%-off and get
instant access to the code depot of Oracle tuning scripts. |
|
|
|
and include the URL for the page.
