讀懂Oracle 10046 SQL TRACE

為什麼我們要使用10046 trace?

 

10046 trace幫助我們解析 一條/多條SQL、PL/SQL語句的執行狀態 ，這些狀態包括 ：Parse/Fetch/Execute三個階段中遇到的等待事件、消耗的物理和邏輯讀、CPU時間、執行計劃等等。

即10046 為我們揭示了 一條/多條SQL 的執行情況， 對於  以點入手的 SQL調優是很好的輔助工具，特別是在 10g之前沒有ASH的情況下。 但整體系統調優 不是10046 所擅長的，  10046 是 效能調優的起釘器 ， AWR是效能調優 的錘子。

 

10046還能幫助我們分析 一些 DDL維護命令的內部工作原理， RMAN、Data Pump Expdp/Impdp等工具的緩慢問題等， 是研究 oracle 資料庫原理的 居家旅行必備良品。

 

10046 和SQL TRACE的區別？

 

10046 比 SQL_TRACE引數提供更多的控制選項， 更詳細的內容輸出， 一般Maclean只用10046 而不用sql_trace

 

10046 和10053 的區別？

 

10053 是最常用的Oracle 優化器optimizer 跟蹤trace， 10053 可以作為我們解析 優化器為什麼選擇某個執行計劃，其中的理由的輔助工具，但並不告訴我們這個執行計劃 到底執行地如何。

而10046 並不解釋 optimizer優化器的工作， 但它同樣說明了在SQL解析parse階段所遇到的等待事件和所消耗的CPU等資源，以及Execute執行和Fetch階段的各項指標。

 

簡而言之10046 告訴我們SQL(執行計劃)執行地如何， 10053告訴我們 優化器為什麼為這個SQL選擇某個執行計劃。

 

 10046 TRACE的LEVEL:

 

不同的Level 對應不同的跟蹤級別

• 1  啟用標準的SQL_TRACE功能 ( 預設)  包含了 SQL語句、響應時間、服務時間、處理的行數，物理讀和寫的數目、執行計劃以及其他一些額外資訊。   到版本10.2中 執行計劃寫入到 trace 的條件是僅當相關遊標 已經關閉時， 且與之相關的執行統計資訊是所有執行次數的總和資料。  到版本11.1中僅在每次遊標的第一次執行後將執行計劃寫入到trace ， 執行統計資訊僅僅和這第一次執行相關
• 4 比level 1時多出 繫結變數的 trace
• 8  比level 1多出等待事件，特別對於9i中指出 latch free等待事件很有用，對於分析全表掃描和索引掃描也很有用
• 12  比level 1 多出 繫結變數和 等待事件
• 16  在11g中為每一次執行生成STAT資訊，僅在11.1之後可用
• 32  比level 1少執行計劃
•  64  和level 1 相比 在第一次執行後還可能生成執行計劃資訊 ； 條件是某個遊標在前一次執行的前提下 執行耗時變長了一分鐘。僅在 11.2.0.2中可用
• Level 28 (4 + 8 + 16) 代表 同時啟用 level 4 、level 8、level 16
• level 68 ( 64 + 4 )  代表 同時啟用 level 64、level 4

 

 

 

 

設定的方法如下：

 

 

session 級別：　alter session set events ’10046  trace name context forever,level X’;

system 級別 :      alter system  set events ’10046  trace name context forever,level X’;

 

針對非本會話的 某一個程式設定，如果你知道他的SPID 作業系統程式號

oradebug setospid SPID;

oradebug event 10046 trace name context forever, level X;

 

例如：

 

[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=44 dep=0 uid=0 oct=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 檢視可以看到完整的對照列表， http://www.askmaclean.com/archives/vsqlcommand-sql-opcodes-and-names.html

 

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 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來獲得當前等待資訊。

 

 

來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/28894640/viewspace-769248/，如需轉載，請註明出處，否則將追究法律責任。