瞭解raw trace檔案的各項內容

今天瀏覽metalink，看到這篇Interpreting Raw SQL_TRACE，比較老的一篇文章了，但是確實很有用，所以決定大略翻譯一下吧。

我們知道有幾種方法可以得到一個SQL語句執行時背景trace檔案，一個是用SQL_TRACE，一個是用DBMS_SUPPORT包或者DBMS_SYSTEM包，還有一種就是直接使用10046 event。

使用10046 event的方法大致如下：

alter session set events '10046 trace name context forever, level 12';<BR>

your sql statement...

alter session set events '10046 trace name context off';

其中的level有1，4，8，12幾個選項，其中1相當於設定SQL_TRACE=TRUE之後的結果，4包括1的結果和綁定變數的實際值，8包括1的結果和等待事件的情況，12則同時包含1的結果，綁定變數的實際值和等待事件情況，所以可以說level 12是最為詳細的trace了。

同時我們也知道，對於trace結果，oracle提供了tkprof公用程式用來格式化trace檔案，提供一份更容易讀懂的trace結果。

那麼為什麼還要直接讀取trace檔案呢？最重要的是tkprof的結果是不包含綁定變數值的，同時也不包括真正的SQL執行順序，而trace檔案中我們則可以看到按照時間排列的parse,binds,executes,fetch等等，這在某西場合下是很有用處的。還有就是，如果你能夠直接讀取這些讓人看得眼暈的trace，是不是會有一種很爽，很大師的感覺:-)

當然如果我們要根據一些標準（比如CPU時間長度，磁碟讀取量等）進行trace中的SQL排序，那麼tkprof是我們唯一的選擇，可以參看coolyl的Tkprof工具介紹和分析。

 

下面是metalink中的這篇文章的大體翻譯，大部分名詞用英文反而更好，就不強加翻譯了，相信大家都看得懂。當然也是比較懶的原因:-)

 

文本總結了trace結果原始輸出檔案中的內容。

 

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

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

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

 

APPNAME：Application name setting。在Oracle 7.2和以上版本中出現。這個名稱可以由DBMS_APPLICATION_INFO包來設定。

mod：Module name

mh：Module hash value

act：Action

ah：Action hash value

 

比如：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語句的長度

dep ：Recursive depth of the cursor，當前SQL語句的遞規深度，如果為0則表示是使用者提交的SQL，為1則是由於使用者SQL而導致Oracle後台自己執行的SQL，為2則是由1級SQL繼續誘發的下一級SQL。

uid ：Schema user id of parsing user

oct ：Oracle command type.

lid ：Privilege user id.

tim ：Timestamp。在Oracle9i之前單位是1/100秒，9i則是1/1,000,000秒。利用這個值可以計算一個SQL執行了到底多長時間。這個值就是當前行被寫入trace檔案時資料庫V$TIMER視圖的值。

hv ：Hash id.

ad ：SQLTEXT address，SQLTEXT的地址，跟V$SQLAREA和V$SQLTEXT視圖中的ADDRESS欄位值相等。

<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 ：在Oracle 7.2以上版本中解析的錯誤會寫入trace檔案中。

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. 解析一個SQL

EXEC ：Execute a pre-parsed statement. 執行已經解析完畢的SQL

FETCH ：Fetch rows from a cursor. 從遊標中得到資料，通常指select返回記錄

UNMAP ：如果遊標使用了暫存資料表（temporary table）, 當遊標關閉的時候將會看到UNMAP

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 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 (large number in 100ths of a second).

 

比如：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

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

 

執行或者fetch之後出現的SQL 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 ']

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

 

<CURSOR>的執行計畫.

<CURSOR> ：Cursor which the statistics apply to.

id ：Line of the explain plan which the row count applies to (從1開始).

cnt ：Number of rows for this row source.

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.

 

比如：

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是事務結束的標誌.

rlbk ：1 if a rollback was performed, 0 if no rollback (commit).

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.

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.

 

比如：

BINDS #4:

 bind 0: dty=2 mxl=22(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(11) 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(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>: nam="<event name>" ela=0 p1=0 p2=0 p3=0

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

 

WAIT ：An event that we waited for.

nam ：What was 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.

 

比如 (Full Table Scan):

WAIT #1: nam="db file scattered read" ela= 5 p1=4 p2=1435 p3=25

在遊標1上經曆了"db file scattered read"等待事件，一共等了0.05秒，在讀取File 4，從1435 block開始，讀了25個block

 

比如 (Index Scan):

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

在遊標1上經曆了"db file sequential read"等待事件，一共等了0.04秒，在讀取file 4，block 1224，讀取了這一個block

 

對於每一個等待事件的含義和p1,p2,p3表示的意思，可以參考Oracle Database Reference文檔的Oracle Wait Events章節。