Understanding the contents of the raw trace file

Today browse Metalink, see this article interpreting Raw Sql_trace, older an article, but really useful, so decided to roughly translate it.

We know there are several ways to get a TRACE file in the background of an SQL statement execution, one with Sql_trace, one with a Dbms_support package or Dbms_system package, and one that uses the 10046 event directly.

The method for using 10046 event is as follows:

Alter session SET Events ' 10046 Trace name context forever, Level ';<br>

Your SQL statement ...

Alter session SET Events ' 10046 Trace name context off ';

The level has 1,4,8,12 several options, of which 1 is equivalent to the result of setting Sql_trace=true, 4 includes 1 results and the actual value of the bound variable, 8 includes 1 results and waiting events, and 12 contains the result of 1, the actual value of the binding variable, and the waiting event situation , so you can say level 12 is the most verbose trace.

We also know that for trace results, Oracle provides the TKPROF utility to format the trace file to provide a more readable trace result.

So why do you want to read the trace file directly? Most importantly, the result of the tkprof is that it does not contain the value of the binding variable, and does not include the actual SQL execution order, while the trace file lets you see the parse,binds,executes,fetch in chronological order and so on, which is useful in a certain western situation. And there is, if you can directly read these Ching trace, there will be a very cool, very great sense of the master:-)

Of course, if we were to sort the SQL in trace based on some criteria, such as CPU length, disk reads, and so on, then tkprof is our only option, and we can refer to Coolyl's Tkprof tool introduction and analysis.



The following is the general translation of this article in Metalink, most nouns in English instead of the imposition of translation, I believe we can understand. Of course, is also lazy reason:-)



The text summarizes the contents of the trace results original output file.



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

APPNAME mod= '%s ' mh=%lu act= '%s ' Ah=%lu

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



Appname:application name setting. Appears in Oracle version 7.2 and above. 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 #<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 statement length

Dep:recursive depth of the cursor, the current recursive depth of the SQL statement, if 0 is the user-submitted SQL, and 1 is the SQL that causes Oracle to run itself in the background because of user SQL, 2 is the next level of SQL that is continued to be induced by Level 1 SQL.

Uid:schema User ID of parsing user

oct:oracle command type.

Lid:privilege User ID.

Tim:timestamp. Before oracle9i, the unit is 1/100 seconds, and the 9i is 1/1,000,000 seconds. This value allows you to calculate how long an SQL has been executed. This value is the value of the database V$timer view when the current row is written to the trace file.

Hv:hash ID.

The address of the Ad:sqltext Address,sqltext is equal to the value of the Addresses field in V$sqlarea and V$sqltext views.

<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 Error: Errors parsed in Oracle version 7.2 are written 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

<statement>: The SQL statement that errored.



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

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

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



Parse:parse a statement. Parsing a SQL

Exec:execute a pre-parsed statement. Execute the parsed SQL

Fetch:fetch rows from a cursor. To get data from a cursor, usually a select return record

Unmap: If the cursor uses a temporary table (temporary table), it will be seen when the cursor is closed unmap

C:cpu time (100th's a second in Oracle7, 8 and 9).

e:elapsed time (100th ' a second Oracle7, 8. Microseconds in Oracle 9 onwards).

P:number of physical reads.

Cr:number of buffers retrieved for CR reads.

Cu:number of buffers retrieved in the 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 (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 that occurred after execution or fetch

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 ']

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



<CURSOR> 's execution plan.

<CURSOR>: CURSOR which the statistics apply to.

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 row source.

Pos:position in explain.

Obj:object ID of Row source (if is a base Object).

Op:the Row Source Access operation.



Like what:

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 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 flag of the end of a transaction.

Rlbk:1 If a rollback was performed, 0 if no rollback (commit).

Rd_only:1 if transaction is read only, 0 if changes occurred.



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

Binds #%d:

Bind 0:dty=2 mxl=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 is 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.



Like what:

Binds #4:

Bind 0:dty=2 mxl=22 mal=00 scl=00 pre=00 oacflg=08 oacfl2=1 size=24 offset=0

Bfp=ffffffff7ce64ee0 bln=22 avl=01 flg=05

Value=0

Bind 1:dty=1 mxl=32 (one) mal=00 scl=00 pre=00 oacflg=18 oacfl2=1 size=32 offset=0

bfp=ffffffff7ce6b128 bln=32 avl=11 flg=05

Value= "tabcompart$"

Bind 2:dty=2 mxl=22 mal=00 scl=00 pre=00 oacflg=08 oacfl2=1 size=24 offset=0

Bfp=ffffffff7ce6bae8 bln=24 avl=02 flg=05

Value=1



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

Wait #<cursor&gt: nam= "<event name>" ela=0 p1=0 p2=0

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



Wait:an event that we waited for.

Nam:what is being waited for.

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.



For example (full Table Scan):

Wait #1: nam= "db file Scattered read" Ela= 5 p1=4 p2=1435 p3=25

The "DB file scattered read" Wait event on cursor 1 was waited for 0.05 seconds, and 25 blocks were read at file 4, starting with 1435 block



For example (Index Scan):

Wait #1: nam= "db file Sequential read" Ela= 4 p1=4 p2=1224 p3=1

The "DB file sequential read" Wait event was experienced on cursor 1, waiting for 0.04 seconds, reading the block at file 4,block 1224



For the meaning of each waiting event and the meaning of P1,P2,P3, refer to the Oracle Wait Events section of the Oracle Database reference documentation.