10046 事件與 10053 事件

發布時間：2020-08-07 07:17:04 來源：ITPUB博客閱讀：176 作者：kunlunzhiying 欄目：建站服務器

有同學一直向Maclean反應希望做一期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=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 視圖可以看到完整的對照列表，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 物理讀的數目

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

向AI問一下細節

中文字幕av专区_日韩电影在线播放_精品国产精品久久一区免费式_av在线免费观看网站

10046 事件與 10053 事件

猜你喜歡

中文字幕av专区_日韩电影在线播放_精品国产精品久久一区免费式_av在线免费观看网站

10046 事件 與 10053 事件

猜你喜歡

最新資訊

相關推薦

相關標簽

10046 事件與 10053 事件