使用 10046 查看執行計畫並讀懂 trace 檔案，10046trace

使用 10046 查看執行計畫並讀懂 trace 檔案，10046trace
查看 sql 執行計畫的方法有許多種, 10046 事件就是其中的一種. 與其他查看 sql 執行計畫不同, 當我們遇到比較複雜的 sql 語句, 我們可以通過 10046 跟蹤 sql 得到執行計畫中每一個步驟的邏輯讀, 物理讀以及花費的時間等. 這種細粒度的跟蹤對於我們分析 sql 效能尤其有用.

一般來說, 使用 10046 事件得到 sql 執行計畫的步驟如下:
1. 啟用當前 session 10046 事件
2. 在當前 session 中執行 sql 語句
3. 關閉當前 session 10046 事件

執行完上述步驟後, 通常會自動產生一個 trace 檔案. 在 oracle 11g 中, trace 檔案一般放在$ORACLE_BASE/diag/rdbms/{database_name}/$ORACLE_SID/trace 目錄下. 如果使用 oradebug 啟用跟蹤 10046後, 可以使用 oradebug tracefile_name 得到剛剛產生的 trace 檔案的完整路徑.

NAME                                 TYPE        VALUE------------------------------------ ----------- ------------------------------background_dump_dest                 string      g:\app\davidd\diag\rdbms\david                                                 \david\trace

剛剛提到的 oradebug 啟用跟蹤 10046 事件, 我想大部分 dba 都會使用. oradebug 是個功能強大非常好用的工具, 使用 oradebug help 將會看到它的功能很多

SQL> oradebug helpHELP           [command]                 Describe one or all commandsSETMYPID                                 Debug current processSETOSPID       <ospid>                   Set OS pid of process to debugSETORAPID      <orapid> ['force']        Set Oracle pid of process to debugSETORAPNAME    <orapname>                Set Oracle process name to debugSHORT_STACK                              Get abridged OS stackCURRENT_SQL                              Get current SQLDUMP           <dump_name> <lvl> [addr]  Invoke named dumpDUMPSGA        [bytes]                   Dump fixed SGADUMPLIST                                 Print a list of available dumpsEVENT          <text>                    Set trace event in processSESSION_EVENT  <text>                    Set trace event in sessionDUMPVAR        <p|s|uga> <name> [level]  Print/dump a fixed PGA/SGA/UGA variableDUMPTYPE       <address> <type> <count>  Print/dump an address with type infoSETVAR         <p|s|uga> <name> <value>  Modify a fixed PGA/SGA/UGA variablePEEK           <addr> <len> [level]      Print/Dump memoryPOKE           <addr> <len> <value>      Modify memoryWAKEUP         <orapid>                  Wake up Oracle processSUSPEND                                  Suspend executionRESUME                                   Resume executionFLUSH                                    Flush pending writes to trace fileCLOSE_TRACE                              Close trace fileTRACEFILE_NAME                           Get name of trace fileLKDEBUG                                  Invoke global enqueue service debuggerNSDBX                                    Invoke CGS name-service debugger-G             <Inst-List | def | all>   Parallel oradebug command prefix-R             <Inst-List | def | all>   Parallel oradebug prefix (return outputSETINST        <instance# .. | all>      Set instance list in double quotesSGATOFILE      <SGA dump dir>            Dump SGA to file; dirname in double quotesDMPCOWSGA      <SGA dump dir>  Dump & map SGA as COW; dirname in double quotesMAPCOWSGA      <SGA dump dir>            Map SGA as COW; dirname in double quotesHANGANALYZE    [level] [syslevel]        Analyze system hangFFBEGIN                                  Flash Freeze the InstanceFFDEREGISTER                             FF deregister instance from clusterFFTERMINST                               Call exit and terminate instanceFFRESUMEINST                             Resume the flash frozen instanceFFSTATUS                                 Flash freeze status of instanceSKDSTTPCS      <ifname>  <ofname>        Helps translate PCs to namesWATCH          <address> <len> <self|exist|all|target>  Watch a region of memoryDELETE         <local|global|target> watchpoint <id>    Delete a watchpointSHOW           <local|global|target> watchpoints        Show  watchpointsDIRECT_ACCESS  <set/enable/disable command | select query> Fixed table accessCORE                                     Dump core without crashing processIPC                                      Dump ipc informationUNLIMIT                                  Unlimit the size of the trace filePROCSTAT                                 Dump process statisticsCALL           <func> [arg1] ... [argn]  Invoke function with arguments

使用 oradebug 跟蹤 10046 命令如下:

SQL> oradebug setmypidStatement processed.// 啟用 10046 事件SQL> oradebug event 10046 trace name context forever,level 12;Statement processed.SQL> select /*+ leading(t3) use_merge(t4) */ *  2  from t3, t4  3  where t3.id = t4.t3_id and t3.n = 1100;10 rows selected.// 在當前 session 關閉 10046 事件SQL> oradebug event 10046 trace name context off;Statement processed.// 使用 oradebug tracefile_name 可以直接看到產生的 trace 檔案的位置SQL> oradebug tracefile_name;g:\app\davidd\diag\rdbms\david\david\trace\david_ora_2176.trc

其中, 10046 按照收集資訊的內容分為以下等級:

Level 0	停用SQL跟蹤，相當於SQL_TRACE=FALSE
Level 1	標準SQL跟蹤，相當於SQL_TRACE=TRUE
Level 4	在level 1的基礎上增加綁定變數的資訊
Level 8	在level 1的基礎上增加等待事件的資訊
Level 12	在level 1的基礎上增加綁定變數和等待事件的資訊

分析讀懂 trace 檔案

現在我們開啟 g:\app\davidd\diag\rdbms\david\david\trace\david_ora_2176.trc 看看產生的 trace 檔案的內容

<pre name="code" class="sql"><pre name="code" class="sql"><pre name="code" class="sql"><pre name="code" class="sql" style="font-size:14px;">PARSING IN CURSOR #22 len=92 dep=0 uid=0 oct=3 lid=0 tim=900460923321 hv=1624778336 ad='34671d90' sqlid='g0rdyg9hdh9m0'select /*+ leading(t3) use_merge(t4) */ *from t3, t4where t3.id = t4.t3_id and t3.n = 1100END OF STMTPARSE #22:c=0,e=10777,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=3831111046,tim=900460923319EXEC #22:c=0,e=29,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3831111046,tim=900460923482WAIT #22: nam='SQL*Net message to client' ela= 2 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=900460923512FETCH #22:c=15625,e=23922,p=0,cr=119,cu=0,mis=0,r=1,dep=0,og=1,plh=3831111046,tim=900460947462WAIT #22: nam='SQL*Net message from client' ela= 221 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=900460947755WAIT #22: nam='SQL*Net message to client' ela= 2 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=900460947803FETCH #22:c=0,e=71,p=0,cr=0,cu=0,mis=0,r=9,dep=0,og=1,plh=3831111046,tim=900460947864STAT #22 id=1 cnt=10 pid=0 pos=1 obj=0 op='MERGE JOIN  (cr=119 pr=0 pw=0 time=28 us cost=193 size=1280 card=10)'STAT #22 id=2 cnt=1 pid=1 pos=1 obj=0 op='SORT JOIN (cr=15 pr=0 pw=0 time=0 us cost=6 size=63 card=1)'STAT #22 id=3 cnt=1 pid=2 pos=1 obj=83550 op='TABLE ACCESS FULL T3 (cr=15 pr=0 pw=0 time=0 us cost=5 size=63 card=1)'STAT #22 id=4 cnt=10 pid=1 pos=2 obj=0 op='SORT JOIN (cr=104 pr=0 pw=0 time=11 us cost=187 size=650000 card=10000)'STAT #22 id=5 cnt=10000 pid=4 pos=1 obj=83552 op='TABLE ACCESS FULL T4 (cr=104 pr=0 pw=0 time=8603 us cost=29 size=650000 card=10000)'

從上面的 trace 檔案我們可以看出 sql 語句經過了 parse(解析) -> exec(執行) -> fetch(從遊標中擷取資料) 幾個過程, 其中第一句說明了當前跟蹤執行的 sql 語句的概況,比如使用遊標號, sql 語句的長度, 遞迴深度等等基本資料:

PARSING IN CURSOR #22 len=92 dep=0 uid=0 oct=3 lid=0 tim=900460923321 hv=1624778336 ad='34671d90' sqlid='g0rdyg9hdh9m0'

cursor	cursor number
len	sql 語句長度
dep	sql 語句遞迴深度
uid	user id
oct	oracle command type
lid	privilege user id
tim	timestamp，時間戳記
hv	hash id
ad	sql address 地址, 用在 v$sqltext
sqlid	sql id

接著, 下面的語句說明了 sql 語句具體的執行過程以及每一個步驟消耗 CPU 的時間等效能指標

PARSE #22:c=0,e=10777,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=3831111046,tim=900460923319EXEC #22:c=0,e=29,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3831111046,tim=900460923482FETCH #22:c=15625,e=23922,p=0,cr=119,cu=0,mis=0,r=1,dep=0,og=1,plh=3831111046,tim=900460947462

c	CPU 限定的時間
e	Elapsed time
p	number of physical reads 物理讀的次數
cr	number of buffers retrieved for CR reads   邏輯讀的資料區塊
cu	number of buffers retrieved in current mode (current 模式讀取的資料區塊)
mis	cursor missed in the cache 庫緩衝中丟失的遊標, 硬解析次數
r	number of rows processed 處理的行數
dep	遞迴深度
og	optimizer mode 【1：all_rows, 2：first_rows, 3：rule, 4：choose】
plh	plan hash value
tim	timestamp 時間戳記

以及執行過程中的發生的等待事件

WAIT #22: nam='SQL*Net message to client' ela= 2 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=900460923512

nam	an event that we waited for 等待事件
ela	此操作消耗的時間
p3	block 塊號
trm	timestamp 時間戳記

最後顯示的是該遊標的執行計畫

STAT #22 id=1 cnt=10 pid=0 pos=1 obj=0 op='MERGE JOIN  (cr=119 pr=0 pw=0 time=28 us cost=193 size=1280 card=10)'STAT #22 id=2 cnt=1 pid=1 pos=1 obj=0 op='SORT JOIN (cr=15 pr=0 pw=0 time=0 us cost=6 size=63 card=1)'STAT #22 id=3 cnt=1 pid=2 pos=1 obj=83550 op='TABLE ACCESS FULL T3 (cr=15 pr=0 pw=0 time=0 us cost=5 size=63 card=1)'STAT #22 id=4 cnt=10 pid=1 pos=2 obj=0 op='SORT JOIN (cr=104 pr=0 pw=0 time=11 us cost=187 size=650000 card=10000)'STAT #22 id=5 cnt=10000 pid=4 pos=1 obj=83552 op='TABLE ACCESS FULL T4 (cr=104 pr=0 pw=0 time=8603 us cost=29 size=650000 card=10000

cnt	當前行源返回的行數
pid	parent id of this row source 當前行源的父結點 id
pos	position in explain plan 執行計畫的位置
obj	object id of row source (if this is a base object)
op	the row source access operation

例如, 執行步驟 merge join 消耗的邏輯讀為 119, 物理讀為 0, 耗費的時間為 28 us, 成本 cost 193，返回 10 條記錄

使用 tkprof 命令翻譯 trace 檔案

我們也可以使用 tkprof 命令對 trace 檔案進行翻譯，得到一個容易理解的 trace 匯總報表檔案

C:\Documents and Settings\davidd> tkprof g:\app\davidd\diag\rdbms\david\david\trace\david_ora_2176.trc d:\trace.trcTKPROF: Release 11.2.0.1.0 - Development on Thu Dec 18 18:51:44 2014Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.

tkprof 翻譯的 trace 檔案的匯總報表如下：

Trace file: g:\app\davidd\diag\rdbms\david\david\trace\david_ora_2176.trcSort options: default********************************************************************************count    = number of times OCI procedure was executedcpu      = cpu time in seconds executing elapsed  = elapsed time in seconds executingdisk     = number of physical reads of buffers from diskquery    = number of buffers gotten for consistent readcurrent  = number of buffers gotten in current mode (usually for update)rows     = number of rows processed by the fetch or execute call********************************************************************************select /*+ leading(t3) use_merge(t4) */ *from t3, t4where t3.id = t4.t3_id and t3.n = 1100call     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        1      0.00       0.00          0          0          0           0Execute      1      0.00       0.00          0          0          0           0Fetch        2      0.00       0.00          0        119          0          10------- ------  -------- ---------- ---------- ---------- ----------  ----------total        4      0.00       0.00          0        119          0          10Misses in library cache during parse: 1Optimizer mode: ALL_ROWSParsing user id: SYSRows     Row Source Operation-------  ---------------------------------------------------     10  MERGE JOIN  (cr=119 pr=0 pw=0 time=0 us cost=193 size=1280 card=10)      1   SORT JOIN (cr=15 pr=0 pw=0 time=0 us cost=6 size=63 card=1)      1    TABLE ACCESS FULL T3 (cr=15 pr=0 pw=0 time=0 us cost=5 size=63 card=1)     10   SORT JOIN (cr=104 pr=0 pw=0 time=0 us cost=187 size=650000 card=10000)  10000    TABLE ACCESS FULL T4 (cr=104 pr=0 pw=0 time=8733 us cost=29 size=650000 card=10000)Elapsed times include waiting on following events:  Event waited on                             Times   Max. Wait  Total Waited  ----------------------------------------   Waited  ----------  ------------  SQL*Net message to client                       2        0.00          0.00  SQL*Net message from client                     2       20.23         20.23********************************************************************************OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTScall     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        1      0.00       0.00          0          0          0           0Execute      1      0.00       0.00          0          0          0           0Fetch        2      0.00       0.00          0        119          0          10------- ------  -------- ---------- ---------- ---------- ----------  ----------total        4      0.00       0.00          0        119          0          10Misses in library cache during parse: 1Elapsed times include waiting on following events:  Event waited on                             Times   Max. Wait  Total Waited  ----------------------------------------   Waited  ----------  ------------  SQL*Net message to client                       3        0.00          0.00  SQL*Net message from client                     3       20.23         30.20OVERALL TOTALS FOR ALL RECURSIVE STATEMENTScall     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        0      0.00       0.00          0          0          0           0Execute      0      0.00       0.00          0          0          0           0Fetch        0      0.00       0.00          0          0          0           0------- ------  -------- ---------- ---------- ---------- ----------  ----------total        0      0.00       0.00          0          0          0           0Misses in library cache during parse: 0    1  user  SQL statements in session.    0  internal SQL statements in session.    1  SQL statements in session.********************************************************************************Trace file: g:\app\davidd\diag\rdbms\david\david\trace\david_ora_2176.trcTrace file compatibility: 11.1.0.7Sort options: default       1  session in tracefile.       1  user  SQL statements in trace file.       0  internal SQL statements in trace file.       1  SQL statements in trace file.       1  unique SQL statements in trace file.     122  lines in trace file.       0  elapsed seconds in trace file.

其中，Misses in library cache during parse ：1   意思是解析的時候庫緩衝丟失遊標,  也就是說發生了一次硬解析

參考: http://www.eygle.com/archives/2005/10/aeearaw_traceia.html