Wednesday, January 07, 2009

How to read a trace file (10046 trace file)

Event 10046 Raw Output:
~~~~~~~~~~~~~~~~~~~~~~
----------------------------------------------------------------------------
APPNAME mod='%s' mh=%lu act='%s' ah=%lu
----------------------------------------------------------------------------
APPNAME is the application name setting. This only applies to Oracle 7.2
onwards. This can be set by using the DBMS_APPLICATION_INFO package.
See Note:30366.1.

mod Module name
mh Module hash value
act Action
ah Action hash value

----------------------------------------------------------------------------
PARSING IN CURSOR #%d; len=X dep=X uid=X oct=X lid=X tim=X hv=X ad='X'
END OF STMT
----------------------------------------------------------------------------
CURSOR Cursor Number
len Length of SQL statement
dep PGA Depth
uid Schema user id of parsing user
oct Oracle Command Type
lid Privilege user id
tim Timestamp (100th's of a second)
Can be used to determine times between points in the trace file.
hv Hash ID
ad SQLTEXT address (See V$SQLTEXT)

statement The actual SQL statement being parsed

----------------------------------------------------------------------------
PARSE ERROR #%d:len=%ld dep=%d uid=%ld oct=%d lid=%ld tim=%lu err=%d statement...
----------------------------------------------------------------------------

PARSE ERROR In Oracle 7.2+ we report parse errors.

len length of SQL statement
dep PGA Depth
uid User ID
oct Oracle Command Type (if known)
lid Privilege user id
tim Timestamp
err Error reported

statement The SQL statement that errored. If this contains a password
the statement is truncated as indicated by '...' at the end.

----------------------------------------------------------------------------
PARSE #%d :c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=0
EXEC #%d:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=0
FETCH #%d:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=0
UNMAP #%d:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=0
----------------------------------------------------------------------------
- OPERATIONS:

PARSE Parse a statement
EXEC Execute a pre-parsed statement
FETCH Fetch rows from a cursor
UNMAP If the cursor uses a temporary table then when the cursor is
closed you see an UNMAP when we free up the temporary table
locks. (ie: free the lock, delete the state object, free the
temp segment)
In tkprof UNMAP stats get added to the EXECUTE statistics.
SORT UNMAP
As above but for OS file sorts or TEMP table segments.

c CPU time (100th's of a second)
e Elapsed time (100th's of a second)
p Number of physical reads
cr Number of buffers gotten for CR reads
cu Number of buffers gotten 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:
KKOSHARW 1 All_Rows
KKOSHFRW 2 First_Rows
KKOSHRUL 3 Rule
KKOSHCHO 4 Choose
tim Timestamp (large number in 100th's of a second)
Use this to determine the time between any 2 operations.

----------------------------------------------------------------------------
ERROR #%d:err=%d tim=%lu
----------------------------------------------------------------------------
SQL Error shown after an execution or fetch error.

err Oracle error code at the top of the stack.
tim Timestamp

----------------------------------------------------------------------------
STAT #%d id=N cnt=0
----------------------------------------------------------------------------

STAT lines report explain plan statistics for the numbered %d.

%d Cursor which the statistics apply to
id Line of the explain plan 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.


----------------------------------------------------------------------------
XCTEND rlbk=%d rd_only=%d
----------------------------------------------------------------------------
XCTEND is a transaction end marker.

rlbk 1 if a rollback was performed, 0 if no rollback (commit)
rd_only 1 if transaction was read only. 0 is changes occurred.

----------------------------------------------------------------------------

==========================================================
Special output option from non default 10046 trace levels:
==========================================================

----------------------------------------------------------------------------
BINDS #%d:
bind 0: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=08
bfp=088058a8 bln=22 avl=03 flg=0d
value=1379
----------------------------------------------------------------------------

BIND variables bound to a cursor.
This is only reported if Event:10046 is used with the level 4 bit on
(00000100)

bind N The bind position being bound.
dty Data type. See Glossary:DataTypes
mxl Maximum length of the bind variable (private max len in paren)
mal Array length
scl Scale
pre Precision
oacflg See uacdef.h.
UACFIND 0x01 true if using indicators
UACFALN 0x02 true if using length vector
UACFRCP 0x04 true if returning retcodes
UACFBBV 0x08 true if bind by value
UACFBPW 0x10 true if piecewise bind
UACFBLP 0x20 true if blank pad/strip
UACFARR 0x40 true if vector object
UACFIGN 0x80 Ignore this bind/define.
Used for delayed upi
bfp Bind address
bln Bind buffer length
avl Actual value length (array length too)
flg See kxs.h
KXSBFBBV 0x01 Bound By Value
KXSBFBBR 0x02 Bound By Reference
KXSBFRBD 0x04 ReBounD
KXSBFARR 0x08 object is an ARRay
KXSBFLNG 0x10 object is LoNG
KXSBFOST 0x20 Out SeT: used to indicate pl/sql out
variable set
KXSBFBUC 0x40 Bind used in child cursor
KXSBFPBN 0x80 Parent bind variable

value The actual value of the bind variable.
Numbers show the numeric value, strings show the string
etc...

It is also possible to see "bind 6: (No oacdef for this bind)" if no
separate bind buffer exists.

----------------------------------------------------------------------------
WAIT #%d: nam=eventname ela=0 p1=0 p2=0 p3=0
----------------------------------------------------------------------------

WAIT An event that we waited for.
This is only reported if Event:10046 is used with
the level 8 bit on (00001000)

nam What is being waited for - See WaitEvents
ela Elapsed time for the operation
p1 P1 for the given wait event
p2 P2 for the given wait event
p3 P3 for the given wait event
For p1-p3 see the relevent wait-event article.

Example (Full Table Scan):
WAIT #1: nam=db file scattered read; ela= 5 p1=4 p2=1435 p3=25

WAITing under CURSOR no 1
for db file scattered read
We waited 0.05 seconds
For a read of: File 4, start block 1435, for 25 Oracle blocks

Example (Index Scan):
WAIT #1: nam=db file sequential read; ela= 4 p1=4 p2=1224 p3=1

WAITing under CURSOR no 1
for db file sequential read
We waited 0.04 seconds for a single block read (p3=1)
from file 4, block 1224

Reference:
http://tonguc.yilmaz.googlepages.com/ev10046.txt - the
above data is completely from the link I have given
here. You can refer to above link for a clear formatted
one if the above data is not clear.

No comments: