Today, browse Metalink, see this Interpreting Raw SQL_TRACE, a more old article, but it is really useful, so I decided to translate it.
We know that there are several ways to get a SQL statement to execute the TRACE file in the background, one is to use SQL_TRACE, one is with the dbms_support package or dbms_system package, and one is to use 10046 Event.
The method of using 10046 EVENT is approximately as follows:
Alter Session Set Events '10046 Trace Name Context Forever, Level 12';
Your SQL Statement ...
Alter Session Set Events '10046 Trace Name Context Off';
Among them, there are 1, 4, 8, 12 options, where 1 corresponds to the result after setting SQL_TRACE = TRUE, 4 includes 1 results and the actual value of the bound variable, 8 including 1 results and waiting events 12 At the same time, 12 results, the actual value of the bound variable, and waiting for the event, so it can be said that Level 12 is the most detailed trace.
At the same time, we also know that for trace results, Oracle provides TKPROF utilities to format the Trace file, providing a TRACE result that is easier to read.
So why should I read the trace file directly? The most important thing is that the result of TKPROF does not contain binding variables, and does not include the true SQL execution order, and we can see Parse, Binds, Executes, Fetch, etc., etc. in the trace file. It is very useful in a certain west. Also, if you can directly read these people who can see the dark trace, there will be a very cool, very master's feeling :-)
Of course, if we must perform SQL sort in TRACE according to some standards (such as CPU duration, disk reading, etc.), TkProf is our unique choice, you can see the COOLY TKPROF tool introduction and analysis.
Below is a general translation of this article in Metalink, most of the nouns are better in English, do not impose translation, I believe everyone can understand. Of course, it is also a lazy reason :-)
Text summarizes the contents of the trace result raw output file.
-------------------------------------------------- ----------------------------
Appname mod = '% s' MH =% lu act = '% s' ah =% lu
-------------------------------------------------- ----------------------------
AppName: Application Name Setting. The Oracle 7.2 appears in the above version. This name can be set by the dbms_Application_info package.
MOD: MODULE NAME
MH: Module Hash Value
ACT: Action
AH: Action Hash Value
For example: appname mod = 'sql * plus' MH = 3669949024 ACT =' ah = 4029777240
-------------------------------------------------- -------------------------- Parsing in Cursor #
End of stmt
-------------------------------------------------- ----------------------------
LEN: Length of Sql Statement, SQL statement length
Dep: Recursive Depth of the Cursor, the reputation depth of the current SQL statement, if 0 is a SQL submitted by the user, which is due to user SQL, which causes the Oracle's backstage to execute SQL, 2 is 1 SQL continues to induce the next level SQL.
Uid: Schema User ID of Parsing User
Oct: Oracle Command Type.
LID: Privilege User ID.
Tim: TimeStamp. The unit in Oracle9i is 1/100 seconds, 9i is 1 / 1,000,000 seconds. Using this value can calculate how long it has been executed in the end. This value is the value of the database V $ Timer view when the current row is written to the trace file.
HV: hash ID.
AD: SQLText Address, SqlText's address, equal to the Address field value in the V $ SQLAREA and V $ SQLText view.
-------------------------------------------------- ----------------------------
PARSE ERROR #% D: LEN =% LD Dep =% D UID =% LD OCT =% D LID =% LD TIM =% Lu Err =% D
-------------------------------------------------- ----------------------------
PARSE Error: Errors parsed in Oracle 7.2 or later will be written in 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
-------------------------------------------------- ----------------------------
Parse #
Fetch #
Unmap #
-------------------------------------------------- ----------------------------
Parse: Parse a statement. Resolution of a SQL
EXECUTE A pre-pased statement. Execute SQL that has been parsed
Fetch: fetch rows from a cursor. Get data from the cursor, usually refer to SELECT return record
Unmap: If the cursor uses a temporary table, you will see unmap when the cursor is turned off.
C: CPU Time (100th's of a second in oracle7, 8 and 9).
E: Elapsed Time (100th's of a second Oracle7, 8. Microseconds in Oracle 9 Onwards).
p: Number of Physical Reads.
Cr: Number of buffers Retrieved for crrads.
Cu: Number of buffers Retrieved in Current Mode.
MIS: CURSOR MISSED IN The Cache.
R: Number of rows proped.
Dep: Recursive Call Depth (0 = User SQL,> 0 = Recursive).
OG: Optimizer Goal: 1 = All_Rows, 2 = first_ROWS, 3 = Rule, 4 = choose
Tim: TimeStamp (Large Number In 100ths of A SECOND).
For example: FETCH # 2: C = 0, E = 106, P = 0, Cr = 3, Cu = 0, MIS = 0, R = 1, DEP = 1, OG = 4, TIM = 6005498548671
-------------------------------------------------- ----------------------------
Error #% D: Err =% D TIM =% lu
-------------------------------------------------- ----------------------------
SQL Error appearing after execution or fetch
Err: Oracle Error Code (E.g. ORA-XXXXX) at the top of the stack.tim: TimeStamp.
-------------------------------------------------- ----------------------------
Stat #
-------------------------------------------------- ----------------------------
ID: Line of the Explain Plan Which The Row Count Applies TO (starting from 1).
CNT: Number of Rows for this Row Source.
PID: Parent id of this rotion.
POS: POSITION IN EXPLAIN PLAN.
Obj: Object ID of Row Source (if this is a base object).
Op: The Row Source Access Operation.
such as:
Stat # 2 id = 2 CNT = 0 pid = 1 POS = 1 Obj = 510 op = 'table access by index rowid object_usage (cr = 2 r = 0 w = 0 TIME = 83 US)'
STAT # 2 ID = 3 CNT = 1 PID = 2 POS = 1 Obj = 511 OP = 'Index Range Scan i_Stats_Obj # (Cr = 1 R = 0 W = 0 TIME = 43 US)'
-------------------------------------------------- ----------------------------
Xctend RLBK =% D rd_only =% D
-------------------------------------------------- ----------------------------
Xctend is the symbol of the end of the business.
RLBK: 1 IF A ROLLBACK WAS Performed, 0 if No Rollback (Commits).
RD_ONLY: 1 IF Transaction Was Read Only, 0 if Changes Occurred.
-------------------------------------------------- ----------------------------
BINDS #% D:
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.
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.
such as:
BINDS # 4:
BIND 0: DTY = 2 MXL = 22 (22) MAL = 00 SCL = 00 pre = 00 oacflg = 08 oacfl2 = 1 size = 24 offset = 0
BFP = ffffffffff7ce64ee0 BLN = 22 avl = 01 flg = 05
Value = 0
BIND 1: DTY = 1 mxl = 32 (11) MAL = 00 SCL = 00 pre = 00 oacflg = 18 oacfl2 = 1 size = 32 offset = 0
BFP = ffffffffff7ce6b128 bln = 32 AVL = 11 flg = 05
Value = "Tabcompart $"
BIND 2: DTY = 2 mxl = 22 (22) MAL = 00 SCL = 00 pre = 00 oacflg = 08 oacfl2 = 1 size = 24 offset = 0
BFP = ffffffffff7ce6bae8 bln = 24 avl = 02 flg = 05
Value = 1
-------------------------------------------------- ----------------------------
Wait #
-------------------------------------------------- ----------------------------
Wait: an es at we waited for.
Nam: What was being waited for.
ELA: ELAPSED TIME for the Operation.p1: p1 for the given wait evenet.
P2: p2 for the given wait evenet.
P3: p3 for the given wait evenet.
For example, Full Table Scan:
Wait # 1: nam = "DB File Scattered Read" ELA = 5 p1 = 4 p2 = 1435 P3 = 25
On the cursor 1, I experienced the "DB File Scattered Read" waiting for the event, a total of 0.05 seconds, read File 4, starting from 1435 block, read 25 blocks
For example (Index Scan):
Wait # 1: nam = "DB File Sequential Read" ELA = 4 p1 = 4 p2 = 1224 P3 = 1
In the cursor 1, I experienced the "DB File Sequential Read" waiting for the event, and waited for 0.04 seconds, read the file 4, block 1224, read this block.
For each wait event, the meaning of the P1, P2, P3, which can be referred to the Oracle Wait Events chapter of the Oracle Database Reference document.
