Interpreting Raw SQL_TRACE output (文档 ID 39817.1)
来源:互联网 发布:中国产业经济数据库 编辑:程序博客网 时间:2024/04/30 03:04
译文:了解raw trace文件的各项内容
APPLIES TO:
Oracle Server - Standard Edition - Version 8.0.3.0 and laterOracle Server - Personal Edition - Version 8.0.3.0 and later
Oracle Server - Enterprise Edition - Version 8.0.3.0 and later
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.
SCOPE
Persons wishing to interpret raw SQL_TRACE output. Expertise level is high.
DETAILS
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.
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 modModule name. mhModule hash value. actAction. ahAction 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. lenLength of SQL statement. depRecursive depth of the cursor. uidSchema id under which SQL was parsed. octOracle command type. lidPrivilege user id. timTimestamp.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 differencebetween 'tim' values to determine an absolute time. hvHash id. adSQLTEXT address (see views V$SQLAREA Note:43761.1 and V$SQLTEXT Note:43764.1). [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 ERRORIn Oracle 7.2+ parse errors are reported to the trace file. lenLength of SQL statement. depRecursive depth of the statement uidUser id. octOracle command type (if known). lidPrivilege user id. tim Timestamp. errOracle error code (e.g. ORA-XXXXX) reported [statement]The SQL statement that errored. If this contains a password,the statement is truncated as indicated by '...' at the end.
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: PARSEParse a statement. EXEC Execute a pre-parsed statement. FETCHFetch rows from a cursor.UNMAPIf the cursor uses a temporary table, when the cursor isclosed you see an UNMAP when we free up the temporary table locks.(Ie: free the lock, delete the state object, free thetemp segment) In tkprof, UNMAP stats get added to the EXECUTE statistics.SORT UNMAPAs above, but for OS file sorts or TEMP table segments. cCPU time (centiseconds prior to 9i, microseconds rounded to centiseconds granularity on 9i and above)eElapsed time (centiseconds prior to 9i, microseconds thereafter)pNumber of physical reads. crNumber of buffers retrieved for CR reads.cuNumber of buffers retrieved in current mode.misCursor missed in the cache.rNumber of rows processed.depRecursive call depth (0 = user SQL, >0 = recursive). ogOptimizer goal: 1=All_Rows, 2=First_Rows, 3=Rule, 4=Choose
timTimestamp (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) depRecursive depth of the cursor type type of close operation
timTimestamp (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. errOracle error code (e.g. ORA-XXXXX) at the top of the stack. timTimestamp.
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. idLine of the explain plan which the row count applies to (startsat line 1). This is effectively the row source row countfor all row sources in the execution tree. cntNumber of rows for this row source. As of 7.3.3 the items in '[...]' are also reported: pidParent id of this row source. posPosition in explain plan. objObject 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. 11g and above: 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. pwPhysical writes. time Elapsed time taken by the operation (in microseconds). costOptimizer cost of the operation. sizeEstimated size (in bytes). cardEstimated Optimizer Cardinality.
XCTEND rlbk=%d rd_only=%d
XCTEND A transaction end marker. rlbk1 if a rollback was performed, 0 if no rollback (commit). rd_only1 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 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 NThe bind position being bound. dtyData type
mxlMaximum length of the bind variable (private max len in paren). malArray length. sclScale. prePrecision. oacflgSpecial 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
valueThe 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
WAITAn 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. p1P1 for the given wait event. p2P2 for the given wait event. p3P3 for the given wait event.
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
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
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
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
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
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: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:94160.1 - Summary of Oracle DATATYPES
- Oracle Database Products > Oracle Database > Oracle Database > Oracle Database - Standard Edition > Generic RDBMS > Database Level Performance Issues (not SQL Tuning)
- Oracle Database Products > Oracle Database > Oracle Database > Oracle Database - Personal Edition > RDBMS > Database Level Performance Issues (not SQL Tuning)
- Oracle Database Products > Oracle Database > Oracle Database > Oracle Database - Enterprise Edition > RDBMS > Database Level Performance Issues (not SQL Tuning)
- 上一篇The DBMS_SUPPORT Package (文档 ID 62294.1)
- 下一篇Init.ora Parameter "_SQLEXEC_PROGRESSION_COST" [Hidden] Reference Note (文档 ID 68955.1)
- Interpreting Raw SQL_TRACE output (文档 ID 39817.1)
- Interpreting Raw SQL_TRACE output (文档 ID 39817.1)
- Interpreting Explain Plan (10g and Above) (文档 ID 1616894.1)
- General SQL_TRACE / 10046 trace Gathering Examples (文档 ID 1274511.1)
- General SQL_TRACE / 10046 trace Gathering Examples (文档 ID 1274511.1)
- How to Enable SQL_TRACE for Another Session or in MTS Using Oradebug(文档 ID 1058210.6)
- 如何收集用来诊断性能问题的10046 Trace(SQL_TRACE) (文档 ID 1523462.1)
- SQL_TRACE
- sql_trace
- sql_trace
- sql_trace
- SQL Server 2005的output子句用法 output inserted.id
- SQL Server 2005的output子句用法 output inserted.id
- How To Collect 10046 Trace (SQL_TRACE) Diagnostics for Performance Issues (Doc ID 376442.1)
- RAW+ASM 的RAC 安装文档
- RAW+ASM 的RAC 安装文档
- RAW+ASM 的RAC 安装文档
- RAW+ASM 的RAC 安装文档
- linux中线程同步和互斥的区别
- elasticsearch-mapping-introduction
- 《SED 单行脚本快速参考》的 perl 实现
- addr2line探秘
- Intent-数据传递
- Interpreting Raw SQL_TRACE output (文档 ID 39817.1)
- ONOS白皮书下篇之ONOS价值主张
- 关于UIScrollview代理方法详解
- js中两个等号(==)和三个等号(===)的区别
- Android中visibility属性VISIBLE、INVISIBLE、GONE的区别
- C# 中的委托和事件
- 随机获取数据库表记录行
- 如何拆分pdf文件的软件下载
- py in