Applies to:
Oracle Server - Standard Edition - Version: 8.0.3.0 to 11.2.0.3 - Release: 8.0.3 to 11.2Oracle Server - Personal Edition - Version: 8.0.3.0 to 11.2.0.3 [Release: 8.0.3 to 11.2]
Oracle Server - Enterprise Edition - Version: 8.0.3.0 to 11.2.0.3 [Release: 8.0.3 to 11.2]
Information in this document applies to any platform.
Purpose
This is a short reference article which summarises the output format of the raw SQL_TRACE output file.
简单总结生成的跟踪文件。
Note: The format may vary slightly between releases. 跟踪文件的格式在不同的版本间略有变化
Standard Output
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: The format may vary slightly between releases. 跟踪文件的格式在不同的版本间略有变化
Scope
Persons wishing to interpret raw SQL_TRACE output. Expertise level is high.Interpreting Raw SQL_TRACE output
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 :
in the trace would be shown as :
in this document with [CURSOR] replacing the cursor number.
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],在本文档中说明在真正的跟踪文件对应区域中的内容所代表的含义，即CURSOR对应的1代表游标编号。
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 mod Module name. mh Module hash value. act Action. ah Action hash value. 该项输出只针对Oracle 7.2,所以不用太观注[CURSOR] Cursor number.游标号 len Length of SQL statement. SQL语句的长度 dep Recursive depth of the cursor.游标的递归尝试 uid Schema id under which SQL was parsed.解析SQL语句的用户ID,即DBA_USERS表中的USER_ID列 oct Oracle command type.Oracle命令类型 lid Privilege user id.不太清楚 ，这儿应该是执行SQL的用户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.时间戳，的9i之前是厘秒，从9i开始是微秒。可以用来决定跟踪文件不同操作的时间间隔 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. Hash值 ad SQLTEXT address (see views V$SQLAREA Note:43761.1 and V$SQLTEXT Note:43764.1).SQL语句在V$SQLAREA和V$SQLTEXT中的地址，可以跟个两个视图的ADDRESS列去相关联，找出对应的SQL语句，【不过这个地址经测试要大写，而跟踪文件中的字母是小写，所以可以注意一下】 [statement] The actual SQL statement being parsed.被解释执行的真实SQL语句PARSING IN CURSOR #[CURSOR] len=X dep=X uid=X oct=X lid=X tim=X hv=X ad='X' [statement] END OF STMTPARSE ERROR In Oracle 7.2+ parse errors are reported to the trace file.从7.2之上开始在报告中出现 len Length of SQL statement.出错的SQL语句长度 dep Recursive depth of the statement 递归尝试 uid User id.用户ID oct Oracle command type (if known). lid Privilege user id. tim Timestamp. err Oracle error code (e.g. ORA-XXXXX) reported Oracle错误编号 [statement] The SQL statement that errored. If this contains a password, the statement is truncated as indicated by '...' at the end.执行错误的SQL语句，如果语句中包含密码，则用....代替密码内容PARSE ERROR #%d:len=%ld dep=%d uid=%ld oct=%d lid=%ld tim=%lu err=%d [statement] ...
下面是执行统计信息- OPERATIONS: 操作 PARSE Parse a statement. 解析语句 EXEC Execute a pre-parsed statement. 执行语句 FETCH Fetch rows from a cursor. 从游标中获取返回记录数，这select中有值 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.在用tkprof工具格式化时，该 指标信息补加到EXECUTE指标上。 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)CPU时间，9i前是厘秒，9i开始是微秒 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). 递归访问深度，用记的SQL递归深度为0，>0为Oracle递归的深度 og Optimizer goal: 1=All_Rows, 2=First_Rows, 3=Rule, 4=Choose 关于优化器的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
tim Timestamp (100th's of sec < 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 < 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 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.
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. 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)"[BIND] Variables bound to a cursor. bind N The bind position being bound. dty Data typeBINDS #[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
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.
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 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.
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 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
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
WAIT #1: nam='library cache: mutex X' ela= 814 idn=3606132107 value=3302829850624 where=4 obj#=-1 tim=995364327604
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
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
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
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
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
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.
References
NOTE:43718.1 - VIEW: "V$SESSION_WAIT" Reference NoteNOTE:43721.1 - VIEW: "V$EVENT_NAME" Reference Note
NOTE:43761.1 - VIEW: "V$SQLAREA" Reference Note
NOTE:43764.1 - VIEW: "V$SQLTEXT" Reference Note
- Oracle Database Products > Oracle Database > Oracle Database > Oracle Server - Standard Edition > Generic RDBMS
- Oracle Database Products > Oracle Database > Oracle Database > Oracle Server - Personal Edition > Generic RDBMS
- Oracle Database Products > Oracle Database > Oracle Database > Oracle Server - Enterprise Edition > RDBMS
参照：Metalink article #39817.1 discusses how to interpret this raw output.
扫一扫
4万+
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
