Creator:            RPOWELL.UK
Subject:            EVENT: 10046 - Interpreting RAW Output      


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