10046 事件 與 10053 事件

[oracle@vrh8 ~]$ ps -ef|grep LOCAL oracle 12421 12420 0 Aug21 ? 00:00:00 oracleG10R25 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq))) oracle 12522 12521 0 Aug21 ? 00:00:00 oracleG10R25 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq))) oracle 12533 1 0 Aug21 ? 00:00:00 oracleG10R25 (LOCAL=NO) oracle 15354 15353 0 Aug21 ? 00:00:08 oracleG10R25 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq))) oracle 15419 15418 0 Aug21 ? 00:00:11 oracleG10R25 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq))) oracle 16219 16218 0 Aug21 ? 00:00:00 oracleG10R25 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq))) oracle 17098 17097 0 03:12 ? 00:00:00 oracleG10R25 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq))) 要跟蹤 17098 這個程式 SQL> oradebug event 10046 trace name context forever, level 28; Statement processed. 從 sid 定位到 SPID 或者 ORAPID 的 查詢如下： SQL> select distinct sid from v$mystat; SID ---------- 141 SQL> select spid,pid from v$Process where addr=(select paddr from v$session where sid=141); SPID PID ------------ ---------- 17196 24 select spid,pid from v$Process where addr=(select paddr from v$session where sid=&SID) 如果只知道 ORA的PID 那麼也可以 oradebug setorapid 24; oradebug event 10046 trace name context forever, level 28;

10046 trace 示例解析

這裡我們引入一個全表掃描的10046例子 並解析該例子中的TRACE資訊：

PARSING IN CURSOR #20 len=44 dep=0 uid=0 ct=3 lid=0 tim=1344883874047619 hv=2241892608 ad='a7902a08' select count(*) from fullscan where wner=:v END OF STMT PARSE #20:c=2000,e=1087,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1344883874047610 PARSING IN CURSOR #26 len=198 dep=1 uid=0 ct=3 lid=0 tim=1344883874048534 hv=4125641360 ad='a7ab9fc0' select obj#,type#,ctime,mtime,stime,status,dataobj#,flags,oid$, spare1, spare2 from obj$ where owner#=:1 and name=:2 and namespace=:3 and remoteowner is null and linkna me is null and subname is null END OF STMT PARSE #26:c=0,e=531,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,tim=1344883874048501 BINDS #26: kkscoacd Bind#0 acdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00 acflg=08 fl2=0001 frm=00 csi=00 siz=24 ff=0 kxsbbbfp=7f9ccfec6bd8 bln=22 avl=01 flg=05 value=0 Bind#1 acdty=01 mxl=32(08) mxlc=00 mal=00 scl=00 pre=00 acflg=18 fl2=0001 frm=01 csi=873 siz=32 ff=0 kxsbbbfp=7f9ccfec6ba0 bln=32 avl=08 flg=05 value="FULLSCAN" askmaclean.com Bind#2 acdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00 acflg=08 fl2=0001 frm=00 csi=00 siz=24 ff=0 kxsbbbfp=7f9ccfec6b70 bln=24 avl=02 flg=05 value=1 EXEC #26:c=1998,e=1506,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,tim=1344883874050177 WAIT #26: nam='db file sequential read' ela= 26 file#=1 block#=58007 blocks=1 obj#=37 tim=1344883874050345 WAIT #26: nam='db file sequential read' ela= 19 file#=1 block#=58966 blocks=1 obj#=18 tim=1344883874050452 PARSING IN CURSOR #25 len=493 dep=1 uid=0 ct=3 lid=0 tim=1344883874051980 hv=2584065658 ad='a7a9ef68' select t.ts#,t.file#,t.block#,nvl(t.bobj#,0),nvl(t.tab#,0),t.intcols,nvl(t.clucols,0),t.audit$,t.flags,t.pctfree$,t.pctused$,t.initrans,t.maxtrans,t.rowcnt,t.blkcnt,t.e mpcnt,t.avgspc,t.chncnt,t.avgrln,t.analyzetime,t.samplesize,t.cols,t.property,nvl(t.degree,1),nvl(t.instances,1),t.avgspc_flb,t.flbcnt,t.kernelcols,nvl(t.trigflag, 0),n vl(t.spare1,0),nvl(t.spare2,0),t.spare4,t.spare6,ts.cachedblk,ts.cachehit,ts.logicalread from tab$ t, tab_stats$ ts where t.obj#= :1 and t.obj# = ts.obj# (+) END OF STMT PARSE #25:c=1000,e=585,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,tim=1344883874051971 BINDS #25: kkscoacd Bind#0 acdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00 acflg=08 fl2=0001 frm=00 csi=00 siz=24 ff=0 kxsbbbfp=7f9ccfec6bd8 bln=22 avl=04 flg=05 value=96551 EXEC #25:c=3000,e=2757,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,tim=1344883874054930 WAIT #25: nam='db file sequential read' ela= 21 file#=1 block#=48756 blocks=1 obj#=3 tim=1344883874055059 WAIT #25: nam='db file sequential read' ela= 18 file#=1 block#=51327 blocks=1 obj#=4 tim=1344883874055149 FETCH #25:c=0,e=538,p=2,cr=5,cu=0,mis=0,r=1,dep=1,og=4,tim=1344883874055512 STAT #25 id=1 cnt=1 pid=0 pos=1 bj=0 p='MERGE JOIN OUTER (cr=5 pr=2 pw=0 time=565 us)' STAT #25 id=2 cnt=1 pid=1 pos=1 bj=4 p='TABLE ACCESS CLUSTER TAB$ (cr=3 pr=2 pw=0 time=228 us)' STAT #25 id=3 cnt=1 pid=2 pos=1 bj=3 p='INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=1 pw=0 time=115 us)' STAT #25 id=4 cnt=0 pid=1 pos=2 bj=0 p='BUFFER SORT (cr=2 pr=0 pw=0 time=251 us)' STAT #25 id=5 cnt=0 pid=4 pos=1 bj=709 p='TABLE ACCESS BY INDEX ROWID TAB_STATS$ (cr=2 pr=0 pw=0 time=207 us)' STAT #25 id=6 cnt=0 pid=5 pos=1 bj=710 p='INDEX UNIQUE SCAN I_TAB_STATS$_OBJ# (cr=2 pr=0 pw=0 time=33 us)' ................ BINDS #20: kkscoacd Bind#0 acdty=96 mxl=2000(150) mxlc=00 mal=00 scl=00 pre=00 acflg=03 fl2=1000000 frm=01 csi=873 siz=2000 ff=0 kxsbbbfp=7f9ccfec6420 bln=2000 avl=50 flg=05 value="MACLEAN " EXEC #20:c=20996,e=21249,p=7,cr=19,cu=0,mis=1,r=0,dep=0,og=1,tim=1344883874068951 WAIT #20: nam='SQL*Net message to client' ela= 6 driver id=1650815232 #bytes=1 p3=0 obj#=36 tim=1344883874069011 WAIT #20: nam='db file sequential read' ela= 23 file#=1 block#=80385 blocks=1 obj#=96551 tim=1344883874069159 WAIT #20: nam='db file scattered read' ela= 42 file#=1 block#=80386 blocks=7 obj#=96551 tim=1344883874069383 WAIT #20: nam='db file scattered read' ela= 41 file#=1 block#=82313 blocks=8 obj#=96551 tim=1344883874069543 WAIT #20: nam='db file scattered read' ela= 30 file#=1 block#=82321 blocks=8 obj#=96551 tim=1344883874069678 WAIT #20: nam='db file scattered read' ela= 38 file#=1 block#=82329 blocks=8 obj#=96551 tim=1344883874069949 WAIT #20: nam='db file scattered read' ela= 848 file#=1 block#=82337 blocks=8 obj#=96551 tim=1344883874070846 WAIT #20: nam='db file scattered read' ela= 63 file#=1 block#=82345 blocks=8 obj#=96551 tim=1344883874071042 WAIT #20: nam='db file scattered read' ela= 37 file#=1 block#=92593 blocks=8 obj#=96551 tim=1344883874071190 WAIT #20: nam='db file scattered read' ela= 73 file#=1 block#=92601 blocks=8 obj#=96551 tim=1344883874071393 FETCH #20:c=18997,e=18234,p=1139,cr=1143,cu=0,mis=0,r=1,dep=0,og=1,tim=1344883874087322 WAIT #20: nam='SQL*Net message from client' ela= 285 driver id=1650815232 #bytes=1 p3=0 obj#=96551 tim=1344883874087675 FETCH #20:c=0,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1344883874087715 WAIT #20: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=96551 tim=1344883874087744 *** 2013-08-22 04:44:59.527 WAIT #20: nam='SQL*Net message from client' ela= 12169104 driver id=1650815232 #bytes=1 p3=0 obj#=96551 tim=1344883886256887 STAT #20 id=1 cnt=1 pid=0 pos=1 bj=0 p='SORT AGGREGATE (cr=1143 pr=1139 pw=0 time=18243 us)' STAT #20 id=2 cnt=0 pid=1 pos=1 bj=96551 p='TABLE ACCESS FULL FULLSCAN (cr=1143 pr=1139 pw=0 time=18200 us)' WAIT #0: nam='SQL*Net message to client' ela= 8 driver id=1650815232 #bytes=1 p3=0 obj#=96551 tim=1344883886257193 WAIT #0: nam='SQL*Net message from client' ela= 455225 driver id=1650815232 #bytes=1 p3=0 obj#=96551 tim=1344883886712468 WAIT #0: nam='SQL*Net message to client' ela= 0 driver id=1650815232 #bytes=1 p3=0 obj#=96551 tim=1344883886712594

PARSING IN CURSOR #20 len=44dep=0 uid=0 ct=3 lid=0 tim=1344883874047619 hv=2241892608 ad=’a7902a08′
select count(*) from fullscan where wner=:v
END OF STMT
PARSE #20:c=2000,e=1087,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1344883874047610

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的長度

OCT=3 Oracle command type 指Oracle中命令分類的型別 可以透過 V$SQL.COMMAND_TYPE獲得對應關係

11g中提供了 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 物理讀的數目

CRCR一致性讀引起的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 rlbk=0, rd_only=1

• XCTEND 一個事務結束的標誌
• 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來獲得當前等待資訊。