Oracle效能分析2：trace檔案解讀

標籤：database   oracle   效能   資料庫   

下面是trace檔案中的一個片段，表示一個SQL執行的過程，一個trace檔案由很多這樣的片段組成：

PARSING IN CURSOR #4 len=135 dep=1 uid=0 oct=3 lid=0 tim=777069789359 hv=1115215392 ad='33e7e384'select /*+ index(idl_char$ i_idl_char1) +*/ piece#,length,piece from idl_char$ where obj#=:1 and part=:2 and version=:3 order by piece#END OF STMTPARSE #4:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=777069789357--BINDS #2:EXEC #4:c=0,e=14,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=777069789415--WAIT #2: nam='SQL*Net message from client' ela= 143 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=775454461373FETCH #4:c=0,e=18,p=0,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=777069789450FETCH #4:c=0,e=5,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,tim=777069789477STAT #4 id=1 cnt=1 pid=0 pos=1 obj=74 op='TABLE ACCESS BY INDEX ROWID IDL_CHAR$ (cr=4 pr=0 pw=0 time=20 us)'STAT #4 id=2 cnt=1 pid=1 pos=1 obj=115 op='INDEX RANGE SCAN I_IDL_CHAR1 (cr=3 pr=0 pw=0 time=12 us)'

以"--"開頭是人為添加的，在其它查詢中可能存在，下面關鍵字段的含義：
 1）PARSING IN CURSOR和END OF STMT包含了SQL語句文本；
 2）PARSE、EXEC和FETCH分別表示解析（parse）、執行（execution）和擷取（fetch）調用；
 3）BINDS表示綁定變數的定義與值；
 4）WAIT表示在處理過程匯總發生的等待事件；
 5）STAT表示產生的執行計畫以及相關的統計。
下面是更細緻的一些解釋（來自：Interpreting Raw SQL_TRACE and DBMS_SUPPORTSTART_TRACE output），由於Oracle每個版本都有差異，所以這些內容僅供參考。

-------------------------------------------------------------------------
PARSING IN CURSOR # len=X dep=X uid=X oct=X lid=X tim=X hv=X ad=‘X‘
SQL語句
END OF STMT
--------------------------------------------------------------------------
len：SQL語句長度
dep：遊標遞迴調用的深度
uid：分析SQL的使用者ID
oct：ORACLE命令類型
lid：特權使用者id
tim：時間抽。ORACLE 9i以前，單位僅僅為1/100秒；ORACLE 9i之後單位為1/1000000秒。時間戳記可以用來決定兩點之間的時間間隔。該數值取自v$timer中的數值，可以用2個操作的‘tim‘差決定絕對時間
hv：SQL HASH ID（對應V$SQLAREA視圖和V$SQLTEXT視圖的HASH_VALUE欄位）
ad：SQLTEXT地址（對應V$SQLAREA視圖和V$SQLTEXT視圖的ADDRESS欄位）

--------------------------------------------------------------------------
PARSE ERROR #%d:len=%ld dep=%d uid=%ld oct=%d lid=%ld tim=%lu err=%d
SQL語句
--------------------------------------------------------------------------
len：SQL語句長度
dep：遊標遞迴調用的深度
uid：分析SQL的使用者ID
oct：ORACLE命令類型
tim：時間抽。同上
err：Oracle錯誤碼（e.g.ORA-XXXXX）

--------------------------------------------------------------------------
PARSE #:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=0 
EXEC  #:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=0
FETCH #:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=0
UNMAP #:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=0
--------------------------------------------------------------------------
操作：
 1）PARSE：解析SQL
 2）EXEC：執行已經分析的SQL
 3）FETCH：從遊標中擷取記錄
 4）UNMAP：如果遊標使用了暫存資料表，當遊標關閉的時候，該操作用來釋放暫存資料表資源（釋放鎖、刪除狀態物件、釋放臨時段等）。在tkprof產生的報告中，UNMAP的統計資訊加入到EXECUTE操作的統計資訊中。
 5）SORT UNMAP：如上類似，但是為OS檔案排序或者TEMP表段（segment）

c：CPU time（1/100秒在Oracle7、8和9）
e：Elapsed time（1/100秒在Oracle7、8，微秒在Oracle 9和之後版本）
p：物理讀（Number of physical reads）
cr：CR（consistent read，一致性讀）讀的數量
cu：在當前模式（current mode）下讀的數量
mis：cursor在緩衝中錯過的數量
r：涉及的記錄數量
dep：遞迴調用深度（0 = user SQL，>0 = recursive）
og：最佳化器模式：1=All_Rows,2=First_Rows,3=Rule,4=Choose
tim：時間戳記，用於確定兩個操作之間的時間

--------------------------------------------------------------------------
ERROR #%d:err=%d tim=%lu
--------------------------------------------------------------------------
一個execution或者tetch錯誤後的錯誤展示
err：在堆棧頂的Oracle錯誤碼（例如：ORA-XXXX）
tim：時間戳記

--------------------------------------------------------------------------
STAT #<CURSOR> id=N cnt=0  [pid=0 pos=0 obj=0 op=‘SORT AGGREGATE ‘]
--------------------------------------------------------------------------
STAT：為<CURSOR>的執行計畫統計報告
<CURSOR>：統計應用到的Cursor
id：執行計畫中個操作在執行計畫樹中的編號
cnt：涉及的行數
pid：這行的父id
pos：在執行計畫中的位置
obj：行的對象id（如果這是一個基本對象）
op：行涉及的操作

--------------------------------------------------------------------------
XCTEND rlbk=%d rd_only=%d
--------------------------------------------------------------------------
XCTEND：事務結束標誌
rlbk：1表示rollback，0表示commit
rd_only：事務唯讀則是1，寫則是0

註：下面的只有當WAITS或者BINDS出現時才存在

--------------------------------------------------------------------------
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：遊標綁定變數

bind N：綁定變數位置
dty：資料類型
mxl：綁定變數最大長度
mal：數組長度
scl：規模（Scale）
pre：進度（precision）
oacflg：表明綁定選項的特定標誌
oacfl2：oacflg的延續
size：為這塊分配的記憶體
offset：為這個綁定緩衝進入這塊的位移量

bfp：綁定地址
bln：綁定緩衝長度
avl：實際值長度（也是數組長度）
flg：表明綁定狀態的特定標誌
value：綁定變數的實際值

--------------------------------------------------------------------------
WAIT #<CURSOR>: nam="" ela=0 p1=0 p2=0 p3=0
--------------------------------------------------------------------------
WAIT：等待事件資訊
nam：等待事件名稱
ela：操作花費的時間
p1：為等待事件提供的參數p1
p2：為等待事件提供的參數p2
p3：為等待事件提供的參數p3

Example (Full Table Scan):        
 WAIT #1: nam="db file scattered read" ela= 5 p1=4 p2=1435 p3=25
   WAITing under CURSOR no 1
   for "db file scattered read"
解讀：我們等待0.05秒。為一個讀：檔案4，開始塊1435，共25塊
 
Example (Index Scan):
 WAIT #1: nam="db file sequential read" ela= 4 p1=4 p2=1224 p3=1
   WAITing under CURSOR no 1
   for "db file sequential read"
解讀：我們等待0.04秒，為單塊讀（p3=1），從檔案4，開始塊1224