*********************************************************************
示例：全表掃描的10046文件解讀
*********************************************************************
注：trace文件略
· PARSING IN CURSOR #20 ：這里的#20是游標號， 這個游標號非常重要， 后面的 FETCH 、WAIT、EXECUTE、PARSE 都通過這個游標號和前面的SQL聯系起來。
注意可以看到 在執行PARSING IN CURSOR #20 后 ,PARSE #20之后沒有緊跟著 #20游標的運行 ，而是跟了 #25、#26游標的運行情況， 仔細看一下 #25和#26他們是 系統遞歸的recursive SQL ，這些遞歸SQL由 用戶的SQL觸發，一般來說是查一些數據字典基表例如 obj$、tab$等，常規情況下 遞歸SQL運行消耗的資源和時間都非常少。
· LEN=44 指SQL的長度
· [O]CT=3 Oracle command type 指Oracle中命令分類的類型 可以通過 V$SQL.COMMAND_TYPE獲得對應關系，11g中提供了 V$SQLCOMMAND 視圖可以看到完整的對照列表，SQL> select command_type,command_name from V$SQLCOMMAND;
· LID=0 權限用戶ID Privilege user id.
· TIM timestamp 一個時間戳， 在9i之前 這個指標的單位是 1/100 s 即 10ms 。 到9i以后單位為 1/1000000 的microsecond 。 這個時間戳可以用來判斷 trace中2個點的時間差。 這個 TIm的值來自于V$TIMER視圖，這個視圖是Oracle內部計時用的。
· DEP=0 代表該SQL的遞歸深入(recursive depth)，因為遞歸SQL可能再引發下一層的遞歸SQL， 如果DEP=0則說明不是遞歸SQL，如果DEP>0則說明是遞歸SQL。
· UID=0 UID即USERID 用以標明是誰在解析這個游標， 如果是0則說明是SYS 用戶， 具體 用戶名和UID對應可以通過如下查詢獲得：
select user#,name from user$;
· OG=1 OG 代表optimizer_mode ，具體對應關系見下表
0 游標不可見 或 優化器環境未合理創建
1 – ALL_ROWS
2 - FIRST_ROWS
3 – RULE
4 – CHOOSE
· mis=0 該指標說明library cache未發生miss，則本次解析 我們沒有需要硬解析 而是采用軟解析或者更好的方式。 硬解析在Oracle中成本是很高的。 注意由于在任何階段包括PARSE/EXECUTE/FETCH階段都可能發生游標被age out的現象，所以在這些階段都會打印mis指標。如果mis>0則說明可能發生了硬解析。
· HV 代表這個SQL 的hash value ， 10g之前沒有SQL_ID 時 主要靠HASH VALUE 來定位一個SQL
· AD 代表SQLTEXT 的地址 來源于 V$SQLAREA.ADDRESS
· err 代表 Oracle錯誤代碼 例如ORA-1555
· PARSE 是SQL運行的第一個階段，解析SQL
· EXEC 是SQL運行的第二個階段，運行已經解析過的語句
· FETCH 從游標中 fetch數據行
· UNMAP 是當游標使用臨時表時，若游標關閉則使用UNMAP釋放臨時表相關的資源，包括釋放鎖和釋放臨時段
· C 比較重要的指標，代表本步操作消耗的CPU 時間片； 9i以后單位為microsecond
· E Elapsed Time ，代表本步操作消耗的自然時間， 9i以后單位為microsecond
這里存在一個問題例如 在例子中PARSE #20:c=2000,e=1087 CPU_TIME> Elapsed time ；理 論上 應當是 Elapsed Time = CPU TIME + WAIT TIME (等待事件的時間)， 但是由于CPU TIME 和Elapsed time使用了不同 的clock時鐘計時，所以在 2者都很短，或者 是CPU敏感的操作時 有可能 CPU TIME> Elapsed time。
相關的BUG 有:
Bug 4161114 : IN V$SQL, CPU_TIME > ELAPSED_TIME
Bug 7603849 : CPU_TIME > ELAPSED_TIME FOR CERTAIN SQL’S IN V$SQL
Bug 7580277 : ELAPSED_TIME SHOWING 0 FOR CERTAIN SQL’S IN V$SQL
Bug 8243074 : INCORRECT ELAPSED_TIME IN V$SQL
該問題可能 在12c中得到修復
· p 物理讀的數目
· CR CR一致性讀引起的buffer get 數目
· CU 當前讀current read 引起的buffer get 數目
· r 處理的行數
· CLOSE #[CURSOR]:c=%u e=%u dep=%d type=%u tim=%u ==》一個游標關閉的例子
· CLOSE游標關閉
· type 關閉游標的操作類型
0 該游標從未被緩存且執行次數小于3次，也叫hard close
1 該游標從未被緩存但執行次數至少3次，若在session cached cursor中有free slot 則將該游標放入session cached cursor
2 該游標從未被緩存但執行次數至少3次，該游標置入session cached cursor的條件是講老的緩存age out掉
3 該游標已經在緩存里，則還會去
· STAT #[CURSOR] id=N cnt=0 [pid=0 pos=0 bj=0 p='SORT AGGREGATE ']
· STAT 相關行反應解釋執行計劃的統計信息
· [CURSOR] 游標號
· id 執行計劃的行數 從1開始
· cnt 該數據源的行數
· pid 該數據源的 父ID
· pos 在執行計劃中的位置
· obj 對應數據源的 object id
· op= 數據源的訪問操作，例如 FULL SCAN
11g 以上還提供如下信息：
STAT #2 id=1 cnt=26 pid=0 pos=1 bj=0 p=’HASH GROUP BY (cr=1143 pr=1139 pw=0 time=61372 us)’
STAT #2 id=2 cnt=77276 pid=1 pos=1 bj=96551 p=’TABLE ACCESS FULL FULLSCAN (cr=1143 pr=1139 pw=0 time=927821 us)’
· CR 代表一致性讀的數量
· PR 代表物理讀的數量
· pw 代表物理寫的數量
· time 單位為microsecond，本步驟的耗時
· cost 本操作的優化器成本
· size 評估的數據源大小，單位為字節
· card 評估的優化器基數Cardinality.
· XCTEND 一個事務結束的標志，如XCTEND rlbk=0, rd_only=1
rlbk 如果是1代表 有回滾操作， 如果是0 代表不會滾 即 commit提交了
rd_only 如果是1代表 事務只讀 ， 如果是0 說明數據改變發生過

##綁定變量
BINDS #20:
kkscoacd
Bind#0
oacdty=96 mxl=2000(150) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=01 csi=873 siz=2000 ff=0
kxsbbbfp=7f9ccfec6420 bln=2000 avl=50 flg=05
value=”MACLEAN
· BINDS #20: 說明 綁定變量 是針對 20號游標的
· kkscoacd 是綁定變量相關的描述符
· Bind#0 說明是第0個變量
· oacdty data type 96 是 ANSI fixed char
· oacflg 代表綁定選項的特殊標志位
· size 為該內存chunk分配的內存大小
· mxl 綁定變量的最大長度
pre precision
scl Scale
kxsbbbfp buffer point
bln bind buffer length
· avl 實際的值的長度
· flg 代表綁定狀態
· value=”MACLEAN 實際的綁定值
如果看到 “bind 6: (No oacdef for this bind)”類似的信息則說明在trace時 還沒有定義綁定數據。 這可能是在trace時游標還沒綁定變量。
WAIT #20: nam=’db file scattered read’ ela= 42 file#=1 block#=80386 blocks=7 obj#=96551 tim=1344883874069383
· WAIT #20 等待 20號游標的相關等待事件
· Nam 等待針對的事件名字，它的P1、P2、P3可以參考視圖V$EVENT_NAME，也可以從V$SESSION、ASH中觀察到等待事件
· ela 本操作的耗時，單位為microsecond
· p1,p2,p3 針對該事件的三個描述參數，見V$EVENT_NAME
在上例中針對 db file scattered read ， P1為文件號， P2為 起始塊號， p3為 讀的塊數， 即db file scattered read 是從 1號文件的第80386 個塊開始一次讀取了7個塊。
注意在10046中 出現的WAIT 行信息 都是 已經結束的等待事件， 而當前等待則不會在trace中出現，直到這個當前等待結束。 你可以通過systemstate dump/errorstack等trace來獲得當前等待信息。

總結

以上是生活随笔為你收集整理的trace文件解读的全部內容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網站內容還不錯，歡迎將生活随笔推薦給好友。