ITPub博客

首页 > Linux操作系统 > Linux操作系统 > Interpreting Raw SQL_TRACE and DBMS_SUPPORT.START_TRACE output

Interpreting Raw SQL_TRACE and DBMS_SUPPORT.START_TRACE output

原创 Linux操作系统 作者:fromeast 时间:2019-03-15 14:30:04 0 删除 编辑
Subject: Interpreting Raw SQL_TRACE and DBMS_SUPPORT.START_TRACE output
  Doc ID: 39817.1 Type: REFERENCE
  Modified Date : 09-DEC-2008 Status: PUBLISHED

Introduction
~~~~~~~~~~~~
  This is a short reference article which summarises the output format
  of the raw SQL_TRACE output file. The second part of the article
  describes the additional trace lines that may be enabled by the 
  DBMS_SUPPORT package. See Note 62294.1 for details of this package.

Note: The format may vary slightly between releases.

----------------------------------------------------------------------------	
APPNAME mod='%s' mh=%lu act='%s' ah=%lu
----------------------------------------------------------------------------	
    APPNAME     Application name setting.  This only applies to Oracle 7.2
                and above.  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 # len=X dep=X uid=X ct=X lid=X tim=X hv=X ad='X'

END OF STMT
----------------------------------------------------------------------------
    	Cursor number.

    len		Length of SQL statement.
    dep		Recursive depth of the cursor.
    uid		Schema id under which SQL was parsed.
    oct		Oracle command type.
    lid		Privilege user id.
    tim		Timestamp.
		Pre-Oracle9i, the times recorded by Oracle only have a resolution 
                of 1/100th of a second (10mS). As of Oracle9i some times are 
                available to microsecond accuracy (1/1,000,000th of a second).
                The timestamp can be used to determine times between points 
                in the trace file.
		The value is the value in V$TIMER when the line was written.
                The timer has platform-specific implementation differences.
		If there are TIMESTAMPS in the file you can use the difference
		between 'tim' values to determine an absolute time.
    hv		Hash id. 
    ad		SQLTEXT address (see views V$SQLAREA Note 43761.1 and V$SQLTEXT Note 43764.1).

    	The actual SQL statement being parsed.

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

    PARSE ERROR	In Oracle 7.2+ parse errors are reported to the trace file.

    len		Length of SQL statement.
    dep		Recursive depth of the statement
    uid		User id.
    oct		Oracle command type (if known).
    lid		Privilege user id.
    tim	 	Timestamp.
    err		Oracle error code (e.g. ORA-XXXXX) reported
        
    	The SQL statement that errored.  If this contains a password,
		the statement is truncated as indicated by '...' at the end.

----------------------------------------------------------------------------
PARSE #:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=0 
EXEC  #:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=0
FETCH #:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=0
UNMAP #: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, 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 (centiseconds prior to 9i, microseconds rounded to 
                centiseconds granularity on 9i and above)
	e	Elapsed time (centiseconds prior to 9i, microseconds thereafter)
	p	Number of physical reads.  
	cr	Number of buffers retrieved for CR 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
	tim	Timestamp (100th's of sec < Oracle9i, Microseconds thereafter)
                Use this to determine the time between any 2 operations.

----------------------------------------------------------------------------
CLOSE #:c=%u e=%u dep=%d type=%u tim=%u
----------------------------------------------------------------------------
   
    CLOSE       cursor is closed
    c           CPU time (centiseconds prior to 9i, 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
	tim	Timestamp (100th's of sec < Oracle9i, Microseconds thereafter)
                Use this to determine the time between any 2 operations.

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

    err		Oracle error code (e.g. ORA-XXXXX) at the top of the stack.
    tim		Timestamp.

----------------------------------------------------------------------------	
STAT # id=N cnt=0  [pid=0 pos=0 bj=0 p='SORT AGGREGATE ']
----------------------------------------------------------------------------	

    STAT        Lines report explain plan statistics for the numbered .

    	Cursor which the statistics apply to.

    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.

    As of 7.3.3 the items in '[...]' are also reported:

    pid		Parent id of this row source.
    pos		Position in explain plan.
    obj		Object id of row source (if this is a base object).
    p='...'	The row source access operation.

    These let you know the 'run time' explain plan.

----------------------------------------------------------------------------
XCTEND rlbk=%d rd_only=%d
----------------------------------------------------------------------------	
    XCTEND      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 if changes occurred.

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


----------------------------------------------------------------------------
RPC Remote Procedure Calls
----------------------------------------------------------------------------

    These are logged and interpreted in a similar manner, here is an example:

RPC CALL:FUNCTION APPS.ARP_TAX_VENDOR.IS_GEOCODE_VALID(P_GEOCODE IN VARCHAR2) RETURN BOOLEAN;
RPC BINDS:
 bind 0: dty=1 bfp=60000000005e4db8 flg=08 avl=09 mxl=30 val="161630280"
 bind 1: dty=3 bfp=60000000005e4df8 flg=02 avl=04 mxl=04 val=00
RPC EXEC:c=0,e=162

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

======================================================================
The items below are only output if WAITS or BINDS are being traced.
These can be enabled with the DBMS_SUPPORT package.
======================================================================

----------------------------------------------------------------------------	
BINDS #%d:
  bind 0: dty=2 mxl=22(22) mal=00 scl=00 pre=00 acflg=03 oacfl2=0 size=24 ffset=0
  bfp=02fedb44 bln=22 avl=00 flg=05
   value=10
----------------------------------------------------------------------------	

    BIND        Variables bound to a cursor.  

    bind N	The bind position being bound.
    dty		Data type
    mxl		Maximum length of the bind variable (private max len in paren).
    mal		Array length.
    scl		Scale.
    pre		Precision.
    oacflg	Special flag indicating bind options
    oacflg2     Continuation of oacflg
    size        Amount of memory to be allocated for this chunk
    offset      Offset into this chunk for this bind buffer

    bfp         Bind address.
    bln	        Bind buffer length. 
    avl	        Actual value length (array length too).
    flg	        Special flag indicating bind status
    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 #: nam="" ela=0 p1=0 p2=0 p3=0
----------------------------------------------------------------------------

    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 Note 43718.1. For any Oracle release a 
                full list of wait events and the values in P1, P2 and P3 below
                can be seen in view V$EVENT_NAME Note 43721.1
    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.

    Example (Full Table Scan) from Oracle9i (elapsed time in microseconds):	

        WAIT #1: nam="db file scattered read" ela=5010 p1=4 p2=1435 p3=25
	
		WAITing under CURSOR no 1
		for "db file scattered read"
		We waited 5010 microseconds i.e. approx. 5 milliseconds
		For a read of:  File 4, start block 1435, for 25 Oracle blocks
        
    Example (Index Scan) from Oracle8i (elapsed time in centiseconds):

        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	

来自 “ ITPUB博客 ” ,链接:http://blog.itpub.net/418/viewspace-584892/,如需转载,请注明出处,否则将追究法律责任。

请登录后发表评论 登录
全部评论

注册时间:2001-09-29

  • 博文量
    599
  • 访问量
    441133