trace文件解读
*********************************************************************
示例:全表掃描的10046文件解讀
*********************************************************************
注:trace文件略
· PARSING IN CURSOR #20 :這里的#20是游標(biāo)號(hào), 這個(gè)游標(biāo)號(hào)非常重要, 后面的 FETCH 、WAIT、EXECUTE、PARSE 都通過這個(gè)游標(biāo)號(hào)和前面的SQL聯(lián)系起來。
注意可以看到 在執(zhí)行PARSING IN CURSOR #20 后 ,PARSE #20之后沒有緊跟著 #20游標(biāo)的運(yùn)行 ,而是跟了 #25、#26游標(biāo)的運(yùn)行情況, 仔細(xì)看一下 #25和#26他們是 系統(tǒng)遞歸的recursive SQL ,這些遞歸SQL由 用戶的SQL觸發(fā),一般來說是查一些數(shù)據(jù)字典基表例如 obj$、tab$等,常規(guī)情況下 遞歸SQL運(yùn)行消耗的資源和時(shí)間都非常少。
· LEN=44 指SQL的長度
· [O]CT=3 Oracle command type 指Oracle中命令分類的類型 可以通過 V$SQL.COMMAND_TYPE獲得對(duì)應(yīng)關(guān)系,11g中提供了 V$SQLCOMMAND 視圖可以看到完整的對(duì)照列表,SQL> select command_type,command_name from V$SQLCOMMAND;
· LID=0 權(quán)限用戶ID Privilege user id.
· TIM timestamp 一個(gè)時(shí)間戳, 在9i之前 這個(gè)指標(biāo)的單位是 1/100 s 即 10ms 。 到9i以后單位為 1/1000000 的microsecond 。 這個(gè)時(shí)間戳可以用來判斷 trace中2個(gè)點(diǎn)的時(shí)間差。 這個(gè) TIm的值來自于V$TIMER視圖,這個(gè)視圖是Oracle內(nèi)部計(jì)時(shí)用的。
· DEP=0 代表該SQL的遞歸深入(recursive depth),因?yàn)檫f歸SQL可能再引發(fā)下一層的遞歸SQL, 如果DEP=0則說明不是遞歸SQL,如果DEP>0則說明是遞歸SQL。
· UID=0 UID即USERID 用以標(biāo)明是誰在解析這個(gè)游標(biāo), 如果是0則說明是SYS 用戶, 具體 用戶名和UID對(duì)應(yīng)可以通過如下查詢獲得:
select user#,name from user$;
· OG=1 OG 代表optimizer_mode ,具體對(duì)應(yīng)關(guān)系見下表
0 游標(biāo)不可見 或 優(yōu)化器環(huán)境未合理創(chuàng)建
1 – ALL_ROWS
2 - FIRST_ROWS
3 – RULE
4 – CHOOSE
· mis=0 該指標(biāo)說明library cache未發(fā)生miss,則本次解析 我們沒有需要硬解析 而是采用軟解析或者更好的方式。 硬解析在Oracle中成本是很高的。 注意由于在任何階段包括PARSE/EXECUTE/FETCH階段都可能發(fā)生游標(biāo)被age out的現(xiàn)象,所以在這些階段都會(huì)打印mis指標(biāo)。如果mis>0則說明可能發(fā)生了硬解析。
· HV 代表這個(gè)SQL 的hash value , 10g之前沒有SQL_ID 時(shí) 主要靠HASH VALUE 來定位一個(gè)SQL
· AD 代表SQLTEXT 的地址 來源于 V$SQLAREA.ADDRESS
· err 代表 Oracle錯(cuò)誤代碼 例如ORA-1555
· PARSE 是SQL運(yùn)行的第一個(gè)階段,解析SQL
· EXEC 是SQL運(yùn)行的第二個(gè)階段,運(yùn)行已經(jīng)解析過的語句
· FETCH 從游標(biāo)中 fetch數(shù)據(jù)行
· UNMAP 是當(dāng)游標(biāo)使用臨時(shí)表時(shí),若游標(biāo)關(guān)閉則使用UNMAP釋放臨時(shí)表相關(guān)的資源,包括釋放鎖和釋放臨時(shí)段
· C 比較重要的指標(biāo),代表本步操作消耗的CPU 時(shí)間片; 9i以后單位為microsecond
· E Elapsed Time ,代表本步操作消耗的自然時(shí)間, 9i以后單位為microsecond
這里存在一個(gè)問題例如 在例子中PARSE #20:c=2000,e=1087 CPU_TIME> Elapsed time ;理 論上 應(yīng)當(dāng)是 Elapsed Time = CPU TIME + WAIT TIME (等待事件的時(shí)間), 但是由于CPU TIME 和Elapsed time使用了不同 的clock時(shí)鐘計(jì)時(shí),所以在 2者都很短,或者 是CPU敏感的操作時(shí) 有可能 CPU TIME> Elapsed time。
相關(guān)的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中得到修復(fù)
· p 物理讀的數(shù)目
· CR CR一致性讀引起的buffer get 數(shù)目
· CU 當(dāng)前讀current read 引起的buffer get 數(shù)目
· r 處理的行數(shù)
· CLOSE #[CURSOR]:c=%u e=%u dep=%d type=%u tim=%u ==》一個(gè)游標(biāo)關(guān)閉的例子
· CLOSE游標(biāo)關(guān)閉
· type 關(guān)閉游標(biāo)的操作類型
0 該游標(biāo)從未被緩存且執(zhí)行次數(shù)小于3次,也叫hard close
1 該游標(biāo)從未被緩存但執(zhí)行次數(shù)至少3次,若在session cached cursor中有free slot 則將該游標(biāo)放入session cached cursor
2 該游標(biāo)從未被緩存但執(zhí)行次數(shù)至少3次,該游標(biāo)置入session cached cursor的條件是講老的緩存age out掉
3 該游標(biāo)已經(jīng)在緩存里,則還會(huì)去
· STAT #[CURSOR] id=N cnt=0 [pid=0 pos=0 bj=0 p='SORT AGGREGATE ']
· STAT 相關(guān)行反應(yīng)解釋執(zhí)行計(jì)劃的統(tǒng)計(jì)信息
· [CURSOR] 游標(biāo)號(hào)
· id 執(zhí)行計(jì)劃的行數(shù) 從1開始
· cnt 該數(shù)據(jù)源的行數(shù)
· pid 該數(shù)據(jù)源的 父ID
· pos 在執(zhí)行計(jì)劃中的位置
· obj 對(duì)應(yīng)數(shù)據(jù)源的 object id
· op= 數(shù)據(jù)源的訪問操作,例如 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 代表一致性讀的數(shù)量
· PR 代表物理讀的數(shù)量
· pw 代表物理寫的數(shù)量
· time 單位為microsecond,本步驟的耗時(shí)
· cost 本操作的優(yōu)化器成本
· size 評(píng)估的數(shù)據(jù)源大小,單位為字節(jié)
· card 評(píng)估的優(yōu)化器基數(shù)Cardinality.
· XCTEND 一個(gè)事務(wù)結(jié)束的標(biāo)志,如XCTEND rlbk=0, rd_only=1
rlbk 如果是1代表 有回滾操作, 如果是0 代表不會(huì)滾 即 commit提交了
rd_only 如果是1代表 事務(wù)只讀 , 如果是0 說明數(shù)據(jù)改變發(fā)生過
##綁定變量
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: 說明 綁定變量 是針對(duì) 20號(hào)游標(biāo)的
· kkscoacd 是綁定變量相關(guān)的描述符
· Bind#0 說明是第0個(gè)變量
· oacdty data type 96 是 ANSI fixed char
· oacflg 代表綁定選項(xiàng)的特殊標(biāo)志位
· size 為該內(nèi)存chunk分配的內(nèi)存大小
· mxl 綁定變量的最大長度
pre precision
scl Scale
kxsbbbfp buffer point
bln bind buffer length
· avl 實(shí)際的值的長度
· flg 代表綁定狀態(tài)
· value=”MACLEAN 實(shí)際的綁定值
如果看到 “bind 6: (No oacdef for this bind)”類似的信息則說明在trace時(shí) 還沒有定義綁定數(shù)據(jù)。 這可能是在trace時(shí)游標(biāo)還沒綁定變量。
WAIT #20: nam=’db file scattered read’ ela= 42 file#=1 block#=80386 blocks=7 obj#=96551 tim=1344883874069383
· WAIT #20 等待 20號(hào)游標(biāo)的相關(guān)等待事件
· Nam 等待針對(duì)的事件名字,它的P1、P2、P3可以參考視圖V$EVENT_NAME,也可以從V$SESSION、ASH中觀察到等待事件
· ela 本操作的耗時(shí),單位為microsecond
· p1,p2,p3 針對(duì)該事件的三個(gè)描述參數(shù),見V$EVENT_NAME
在上例中針對(duì) db file scattered read , P1為文件號(hào), P2為 起始?jí)K號(hào), p3為 讀的塊數(shù), 即db file scattered read 是從 1號(hào)文件的第80386 個(gè)塊開始一次讀取了7個(gè)塊。
注意在10046中 出現(xiàn)的WAIT 行信息 都是 已經(jīng)結(jié)束的等待事件, 而當(dāng)前等待則不會(huì)在trace中出現(xiàn),直到這個(gè)當(dāng)前等待結(jié)束。 你可以通過systemstate dump/errorstack等trace來獲得當(dāng)前等待信息。
總結(jié)
- 上一篇: 关于单表5-10亿行记录如何快速查询的问
- 下一篇: 美股周三:三大股指均涨超1%,特斯拉涨逾