Interpreting Raw SQL_TRACE output (Doc ID 39817.1)

张玉龙

于 2019-11-15 15:50:31 发布

阅读量230

点赞数

分类专栏： oracle优化学习

原文链接：https://support.oracle.com/epmos/faces/DocumentDisplay?_afrLoop=523693898607497&parent=DOCUMENT&sourceId=376442.1&id=39817.1&_afrWindowMode=0&_adf.ctrl-state=oxayl4wo0_256

版权

oracle优化学习专栏收录该内容

62 篇文章 4 订阅

订阅专栏

Interpreting Raw SQL_TRACE output (Doc ID 39817.1)

PURPOSE

This is a reference document which summarizes the output format of the raw SQL_TRACE output file. 这是一份参考文档，总结了原始SQL_TRACE输出文件的输出格式。

NOTE: The format may vary slightly between releases. 注：发行版之间的格式可能略有不同。

SCOPE

DBA(s) and SQL Performance Tuning experts who need additional information on how to interpret a raw SQL_TRACE output.

需要有关如何解释原始SQL_TRACE输出的其他信息的DBA和SQL Performance Tuning专家。

DETAILS

NOTE: Square brackets : ( [ and ] ) are used to enclose some sections where specific text has been removed. These are not in the original text and are included for visibility. So, for example : 注意：方括号：( [ and ] ) 用于封闭某些部分，其中某些特定的文本已被删除。这些内容不在原始文本中，并且包含在内以提高可见性。因此，例如：

WAIT #1: nam="event name" ela=0 p1=0 p2=0 p3=0

in the trace would be shown as : 在跟踪中将显示为：

WAIT #[CURSOR]: nam="event name" ela=0 p1=0 p2=0 p3=0

in this document with [CURSOR] replacing the cursor number. 在本文档中，用[CURSOR]代替了游标编号。

Standard Output

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
                应用程序名称设置。 这仅适用于Oracle 7.2及更高版本。 
                可以使用DBMS_APPLICATION_INFO包进行设置。
    mod		Module name.   模块名称
    mh		Module hash value.  模块的hash值
    act		Action.  
    ah		Action hash value.

PARSING IN CURSOR #[CURSOR] len=X dep=X uid=X oct=X lid=X tim=X hv=X ad='X'
[statement]
END OF STMT

[CURSOR] Cursor number.

len Length of SQL statement. SQL语句的长度
dep Recursive depth of the cursor. cursor的递归深度
uid Schema id under which SQL was parsed. 用来解析SQL的Schema ID
oct Oracle command type. Oracle命令类型
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.
在Oracle9i之前，Oracle记录的时间仅具有1/100秒(10mS)的分辨率。
从Oracle9i开始，有些时候可以达到微秒级的精度(1/1,000,000秒)。
时间戳可用于确定跟踪文件中点之间的时间。
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.
该值是写该行时的V$TIMER中的值。 计时器具有特定于平台的实现差异。
如果文件中有TIMESTAMPS，则可以使用'tim'值之间的差来确定绝对时间。
hv Hash id.
ad SQLTEXT address (see views V$SQLAREA Note:43761.1 and V$SQLTEXT Note:43764.1).

[statement] The actual SQL statement being parsed. 实际要解析的SQL语句

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

    PARSE ERROR	In Oracle 7.2+ parse errors are reported to the trace file.
                在Oracle 7.2+中，解析错误会报告到Trace文件中。
    len		Length of SQL statement.   SQL语句的长度。
    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
                报告了Oracle错误代码(e.g. ORA-XXXXX)
    [statement]	The SQL statement that errored.  If this contains a password,
		the statement is truncated as indicated by '...' at the end.
                错误的SQL语句。 如果其中包含密码，则该语句将被截断，如末尾的'...'所示。

PARSE #[CURSOR]:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=0
EXEC #[CURSOR]:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=0
FETCH #[CURSOR]:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=0
UNMAP #[CURSOR]: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) 
                如果游标使用临时表，则在关闭游标时，当我们释放临时表锁时，您会看到一个UNMAP。
                (即：释放锁，删除状态对象，释放临时段)
		In tkprof, UNMAP stats get added to the EXECUTE statistics.
                在tkprof中，UNMAP统计信息被添加到EXECUTE统计信息中。
	SORT UNMAP
		As above, but for OS file sorts or TEMP table segments. 
                如上所述，但适用于OS文件排序或TEMP表段。

	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 &lt; Oracle9i, Microseconds thereafter)
                Use this to determine the time between any 2 operations.

CLOSE #[CURSOR]: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 &lt; 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 #[CURSOR] id=N cnt=0 [pid=0 pos=0 obj=0 op='SORT AGGREGATE ']

    STAT        Lines report explain plan statistics for the numbered [CURSOR].
                此行报告说明编号为[CURSOR]的计划统计信息
    [CURSOR]	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).
    op='...'	The row source access operation.

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

    <strong>11g and above:</strong>

    In 11g the "op=" section has been expanded so that STAT lines contain more information. For example:

STAT #[CURSOR] id=1 cnt=1 pid=0 pos=1 obj=0 
        op='SORT AGGREGATE (cr=6 pr=0 pw=0 time=483 us)'
STAT #[CURSOR] id=2 cnt=14 pid=1 pos=1 obj=75510 
        op='TABLE ACCESS FULL EMP (cr=6 pr=0 pw=0 time=432 us cost=2 size=0 card=14)'

    cr 		Consistent reads.
    pr 		Physical reads.
    pw		Physical writes.
    time      	Elapsed time taken by the operation (in microseconds).
    cost		Optimizer cost of the operation.
    size		Estimated size (in bytes).
    card		Estimated Optimizer Cardinality.

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

Additional Wait/Bind Tracing Output

The items below are only output if WAITS or BINDS are being traced. The following notes explain how to get a sql trace file with WAIT and/or BIND information:

Document 376442.1 How To Collect 10046 Trace (SQL_TRACE) Diagnostics for Performance Issues
Document 21154.1 EVENT: 10046 "enable SQL statement tracing (including binds/waits)"

BINDS #[BIND]:
bind 0: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=03 oacfl2=0 size=24 offset=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...

If a message such as : "bind 6: (No oacdef for this bind)" is seen then this means that there is no bind data defined at the time of the dump. This can mean that the cursor is being dumped before the cursor has been bound, for example. It is also possible to see "bind 6: (No oacdef for this bind)", if no separate bind buffer exists for some other reason.

如果看到诸如: "bind 6: (No oacdef for this bind)"的消息，则表明dump时未定义绑定数据。例如，这可能意味着已在绑定游标之前将其dump。如果由于某些其他原因不存在单独的绑定缓冲区，也可能会看到"bind 6: (No oacdef for this bind)"。

WAIT #[CURSOR]: nam="event name" 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 &lt;Note:43718.1&gt;. 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 &lt;Note:43721.1&gt;
    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.

NOTE: Starting with 11g, Traces have started to replace P1, P2 and P3 with more meaningful phrases related to the actual event in question 注意：从11g开始，跟踪已开始用与所讨论的实际事件相关的更有意义的短语替换P1，P2和P3

11g WAIT Examples

(Index Scan) from Oracle11g (elapsed time in microseconds):

WAIT #6: nam='db file sequential read' ela= 8458 file#=110 block#=63682 blocks=1 obj#=221 tim=506028963546

Explanation: Completed WAITing under CURSOR no 6 for "db file sequential read" We waited 8458 microseconds i.e. approx. 8.5 milliseconds For a read of: File 110, start block 63682, for 1 Oracle block of Object number 221. Timestamp was 506028963546 说明：在CURSOR no 6下完成了对"db file sequential read"的等待。我们等待了8458微秒，即大约8.5毫秒读取以下内容：文件110，起始块63682，对于对象编号为221的1个Oracle块。时间戳为506028963546

WAIT #1: nam='library cache: mutex X' ela= 814 idn=3606132107 value=3302829850624 where=4 obj#=-1 tim=995364327604

Explanation: Completed WAITing under CURSOR no 1 for "library cache: mutex X" We waited 814 microseconds i.e. approx. 0.8 milliseconds To get an eXclusive library cache latch with Identifier 3606132107 value 3302829850624 location 4 It was not associated with any particular object (obj#=-1) Timestamp 995364327604 说明：在"library cache: mutex X"下，在CURSOR no 1下完成了等待。我们等待了814微秒，即大约0.8毫秒要获取具有标识符3606132107值3302829850624位置4的eXclusive库高速缓存锁，它与任何特定对象(obj#=-1) 没有关联时间戳995364327604

9i WAIT 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

Explanation: Completed 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 说明：对于"db file scattered read"，在CURSOR no 1下完成了WAITing。我们等待了5010微秒，即大约5毫秒的读取时间：文件4，起始块1435，用于25个Oracle块

8i WAIT Example

(Index Scan) from Oracle8i (elapsed time in centiseconds):

WAIT #1: nam="db file sequential read" ela=4 p1=4 p2=1224 p3=1

Explanation: Completed 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 说明：对于"db file sequential read"，在CURSOR 1下完成了WAITing。我们等待0.04秒从文件4中读取单个块（p3 = 1），块1224

NOTE: WAIT lines in trace refer to completed waits. The current WAIT cannot be seen in the standard SQL_TRACE trace output. A trace providing a PROCESS STATE or similar is required to see the current wait. 注意：Trace中的WAIT行是指已完成的等待。在标准SQL_TRACE跟踪输出中看不到当前的WAIT。需要跟踪提供过程状态或类似状态才能看到当前的等待。

REFERENCES

NOTE:21154.1 - EVENT: 10046 "enable SQL statement tracing (including binds/waits)"
NOTE:30366.1 - PACKAGE DBMS_APPLICATION_INFO Specification
NOTE:376442.1 - * How To Collect 10046 Trace (SQL_TRACE) Diagnostics for Performance Issues
NOTE:43718.1 - VIEW: "V$SESSION_WAIT" Reference Note
NOTE:43721.1 - VIEW: "V$EVENT_NAME" Reference Note
NOTE:43761.1 - VIEW: "V$SQLAREA" Reference Note
NOTE:43764.1 - VIEW: "V$SQLTEXT" Reference Note
NOTE:7522002.8 - Bug 7522002 - "Jumps back in time" and Repeated timestamps in Cursor Steps in SQL Trace in some platforms