Oracle效能分析1：開啟SQL跟蹤和獲取trace檔案

當Oracle查詢出現效率問題時，我們往往需要了解問題所在，這樣才能針對問題給出解決方案。Oracle提供了SQL執行的trace資訊，其中包含了SQL語句的文字資訊，一些執行統計，處理過程中的等待，以及解析階段（如生成執行計劃）產生的資訊。這些資訊有助於你分解sql語句的服 務時間和等待時間，並瞭解所用資源和同步點的詳細資訊，從而幫助你診斷存在的效能問題。
這篇文章介紹了怎麼開啟SQL跟蹤和獲取trace檔案，詳細資訊如下。

開啟SQL跟蹤

從內部技術細節看，SQL跟蹤是基於10046除錯事件的，下面是支援的等級：

0
禁止除錯事件
1
除錯事件是啟用的。針對每個被處理的

資料庫呼叫，給定如下資訊：SQL語句、響應時間、服務時間
處理的行數、處理的行數、邏輯讀數量、物理讀與寫的數量、執行計劃以及一些額外資訊
4
如果等級1，包括繫結變數的額外資訊。主要是資料型別、精度以及每次執行時所用的值
8
同等級1，加上關於等待時間的細節資訊。為了處理過程中的每個等待，提供如下資訊：等待時間的名字、持續時間，以及一些額外的引數，可標明所等待的資源
12
同時啟動等級4和等級8
在Oracle 9i或者之前，下面SQL語句針對所在會話啟用SQL跟蹤：

?

1	alter session set sql_trace = true

還可通過dbms_session包中的set_sql_trace儲存過程，或者通過dbms_system包的set_sql_tarce_in_session儲存過程方法，但這些都只是在等級1啟用SQL跟蹤，在實踐中用處不大，就不詳述了。
更有用的是指定級別的方式，下面是對所在會話開始等級12的SQL跟蹤：

?

1	alter session set events '10046 trace name context forever, level 12'

對應的對所在會話禁止SQL跟蹤的語句如下：

?

1	alter session set events '10046 trace name context off'

也可以通過dbms_system包中的set_ev儲存過程，這裡也不詳述了，我下面重點講講Oracle 10g之後提供的方法。
Oracle 10g之後提供了dbms_monitor包來開啟或關閉SQL跟蹤，提供了在會話、客戶端、元件以及資料庫層級開啟SQL跟蹤方法，注意只有dba角色的使用者才允許使用。

會話級

下面的PL/SQL為ID為122，序列號為6734的會話開啟第8級的SQL跟蹤：

?

1 2 3 4 5 6

begin   dbms_monitor.session_trace_enable(session_id => 122,                                     serial_num => 6734,                                     waits      => true,                                     binds      => false); end;

session_id
session標識，對應v$session檢視中的SID列，下面是獲取當前會話id的方法：

?

1	select userenv('sid') from dual

serial_num
對應v$session檢視中的SERIAL#列，由於SID會重用，當SID被重用時，SERIAL#增加，獲取方法如下：

?

1	select serial# from v$session where sid = 122

waits
對應v$session檢視中的SQL_TRACE_WAITS，表示等待事件跟蹤是否被啟用，預設為true。

binds
對應v$session檢視中的SQL_TRACE_BINDS，表示繫結跟蹤是否被啟用，預設false。

當執行成功後，v$session檢視中的SQL_TRACE被修改為ENABLED，SQL_TRACE_WAITS和SQL_TRACE_BINDS為你設定的對應值。
下面的PL/SQL用於關閉SQL跟蹤：

?

1 2 3

begin   dbms_monitor.session_trace_disable(session_id => 122, serial_num => 6734); end;

客戶端級

下面的PL/SQL呼叫為所有具有指定客戶端標記的會話開啟第8級的SQL跟蹤：

?

1 2 3 4 5

begin   dbms_monitor.client_id_trace_enable(client_id => 'test',                                       waits     => true,                                       binds     => false); end;

需要注意客戶端標記區分大小寫，可以通過下面的方法看是否設定成功：

?

1 2 3

select primary_id as client_id, waits, binds   from dba_enabled_traces  where trace_type = 'CLIENT_ID'

當設定成功後，每次查詢前指定對應的客戶端標記就可以開啟SQL跟蹤，指定客戶端標記的方法如下：

?

1 2 3 4

begin   DBMS_SESSION.SET_IDENTIFIER('test'); end; //該會話的SQL跟蹤已經開啟

當你為一個session設定了標記後，可以在v$session的client_identifier列檢視該標記。
下面的PL/SQL用於關閉SQL跟蹤：

?

1 2 3

begin   dbms_monitor.client_id_trace_disable(client_id => 'test'); end;

元件級

下面的PL/SQL呼叫為所有具有指定客戶端標記的會話開啟第8級的SQL跟蹤：

?

1 2 3 4 5 6 7 8

begin   dbms_monitor.serv_mod_act_trace_enable(service_name  => 'ly',                                          module_name   => 'PL/SQL Developer',                                          action_name   => 'SQL 視窗 - 新建',                                          waits         => true,                                          binds         => false,                                          instance_name => null); end;

引數中的service_name對應v$session檢視的service_name，module_name對應v$session檢視的的module，action_name對應v$session檢視的action，查詢方式如下：

?

1 2 3

SELECT sid, serial#,             client_identifier, service_name, action, module        FROM V$SESSION

設定之後可以通過如下方法檢視設定：

?

1 2 3 4 5 6 7

select primary_id    as service_name,        qualifier_id1 as module_name,        qualifier_id2  as action_name,        waits,        binds   from dba_enabled_traces  where trace_type = 'SERVICE_MODULE_ACTION'

下面的PL/SQL用於關閉SQL跟蹤：

?

1 2 3 4 5 6

begin   dbms_monitor.serv_mod_act_trace_disable(service_name  => 'ly',                                           module_name   => 'PL/SQL Developer',                                           action_name   => 'SQL 視窗 - 新建',                                           instance_name => null); end;

資料庫級

下面的PL/SQL呼叫開啟了資料庫的12級SQL跟蹤：

?

1 2 3 4 5

begin   dbms_monitor.database_trace_enable(waits         => true,                                      binds         => true,                                      instance_name => null); end;

下面的方法檢視設定是否成功：

?

1 2 3 4 5

select instance_name,        waits,        binds   from dba_enabled_traces  where trace_type = 'DATABASE'

下面的PL/SQL用於關閉SQL跟蹤：

?

1 2 3

begin   dbms_monitor.database_trace_disable(instance_name => null); end;

trace檔案中的計時資訊

下面的語句用於為trace檔案提供計時資訊：

?

1	alter session set timed_statistics = true

一般情況下預設都為true，如果不提供計時資訊，trace檔案就沒有什麼用了，因此開啟SQL跟蹤之前，最好確認一下引數被設定為true。

獲取生成的trace檔案

開啟SQL跟蹤後，會生成一個trace檔案，通過初始化引數user_dump_dest配置其所在目錄，該引數的值可以通過下面方法獲取到：

?

1	select name, value from v$parameter where name = 'user_dump_dest'

但如果我們需要定位到具體的檔案，則需要了解trace檔案的命名。trace檔案的名字是獨立於版本和平臺的，在大部分常見的平臺下，命名結構如下：

{instance name}_{process name}_{process id}.trc

1）instance name
初始化引數instance_name的小寫值。通過v$instance檢視的instance_name列可以得到這個值。
2）process name
產生跟蹤檔案程序的名字的小寫值。對於專有伺服器程序，使用ora，對於共享伺服器程序，可以通過v$diapatcher或 v$shared_server檢視的name列獲得。對於並行從屬程序，可以通過v$px_process檢視server_name列獲得，對於其他 多數後臺程序來說，可以通過v$bgprocess檢視的name列獲得。
3）process id
操作系統層面的程序標記。這個值可以通過v$process檢視的spid列獲取。
根據這些資訊，可以通過下面的方式獲取trace檔名：

?

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20

select s.SID,        s.SERVER,        lower(case                when s.SERVER in ('DEDICATED', 'SHARED') then                 i.INSTANCE_NAME || '_' || nvl(pp.SERVER_NAME, nvl(ss.NAME, 'ora')) || '_' ||                 p.SPID || '.trc'                else                 null              end) as trace_file_name   from v$instance      i,        v$session       s,        v$process       p,        v$px_process    pp,        v$shared_server ss  where s.PADDR = p.ADDR    and s.SID = pp.SID(+)    and s.PADDR = ss.PADDR(+)    and s.TYPE = 'USER'    and s.SID = 'your sid'  order by s.SID

將上面的'your sid'替換為你的session的sid就可以查出指定session生成的trace檔案的名字，session的sid在v$session檢視中得到，或者直接查詢當前session的sid：

?

1	select userenv('sid') from dual

將路徑（user_dump_dest）和檔名結合在一起，我們就得到了trace檔案的完整路徑。

而在Oracel 11g中，查詢當前會話生成的trace檔案則非常簡單：

?

1	select value from v$diag_info where name = 'Default Trace File'

Oracle效能分析2：trace檔案解讀

下面是trace檔案中的一個片段，表示一個SQL執行的過程，一個trace檔案由很多這樣的片段組成：

?

1 2 3 4 5 6 7 8 9 10 11

PARSING IN CURSOR #4 len=135 dep=1 uid=0 oct=3 lid=0 tim=777069789359 hv=1115215392 ad='33e7e384' select /*+ index(idl_char$ i_idl_char1) +*/ piece#,length,piece from idl_char$ where obj#=:1 and part=:2 and version=:3 order by piece# END OF STMT PARSE #4:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=777069789357 --BINDS #2: EXEC #4:c=0,e=14,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=777069789415 --WAIT #2: nam='SQL*Net message from client' ela= 143 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=775454461373 FETCH #4:c=0,e=18,p=0,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=777069789450 FETCH #4:c=0,e=5,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,tim=777069789477 STAT #4 id=1 cnt=1 pid=0 pos=1 obj=74 op='TABLE ACCESS BY INDEX ROWID IDL_CHAR$ (cr=4 pr=0 pw=0 time=20 us)' STAT #4 id=2 cnt=1 pid=1 pos=1 obj=115 op='INDEX RANGE SCAN I_IDL_CHAR1 (cr=3 pr=0 pw=0 time=12 us)'

以"--"開頭是人為新增的，在其它查詢中可能存在，下面關鍵欄位的含義：
1）PARSING IN CURSOR和END OF STMT包含了SQL語句文字；
2）PARSE、EXEC和FETCH分別表示解析（parse）、執行（execution）和獲取（fetch）呼叫；
3）BINDS表示繫結變數的定義與值；
4）WAIT表示在處理過程彙總發生的等待事件；
5）STAT表示產生的執行計劃以及相關的統計。
下面是更細緻的一些解釋（來自：Interpreting Raw SQL_TRACE andDBMS_SUPPORTSTART_TRACE output），由於Oracle每個版本都有差異，所以這些內容僅供參考。

-------------------------------------------------------------------------
PARSING IN CURSOR # len=X dep=X uid=X oct=X lid=X tim=X hv=X ad='X'
SQL語句
END OF STMT
--------------------------------------------------------------------------
len：SQL語句長度
dep：遊標遞迴呼叫的深度
uid：分析SQL的使用者ID
oct：ORACLE命令型別
lid：特權使用者id
tim：時間抽。ORACLE 9i以前，單位僅僅為1/100秒；ORACLE 9i之後單位為1/1000000秒。時間戳可以用來決定兩點之間的時間間隔。該數值取自v$timer中的數值，可以用2個操作的'tim'差決定絕對時間
hv：SQL HASH ID（對應V$SQLAREA檢視和V$SQLTEXT檢視的HASH_VALUE欄位）
ad：SQLTEXT地址（對應V$SQLAREA檢視和V$SQLTEXT檢視的ADDRESS欄位）

--------------------------------------------------------------------------
PARSE ERROR #%d:len=%ld dep=%d uid=%ld oct=%d lid=%ld tim=%lu err=%d
SQL語句
--------------------------------------------------------------------------
len：SQL語句長度
dep：遊標遞迴呼叫的深度
uid：分析SQL的使用者ID
oct：ORACLE命令型別
tim：時間抽。同上
err：Oracle錯誤程式碼（e.g.ORA-XXXXX）

--------------------------------------------------------------------------
PARSE #:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=0
EXEC #:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=0
FETCH #:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=0
UNMAP #:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=0
--------------------------------------------------------------------------
操作：
1）PARSE：解析SQL
2）EXEC：執行已經分析的SQL
3）FETCH：從遊標中獲取記錄
4）UNMAP：如果遊標使用了臨時表，當遊標關閉的時候，該操作用來釋放臨時表資源（釋放鎖、刪除狀態物件、釋放臨時段等）。在tkprof產生的報告中，UNMAP的統計資訊加入到EXECUTE操作的統計資訊中。
5）SORT UNMAP：如上類似，但是為OS檔案排序或者TEMP表段（segment）

c：CPU time（1/100秒在Oracle7、8和9）
e：Elapsed time（1/100秒在Oracle7、8，微秒在Oracle9和之後版本）
p：物理讀（Number of physical reads）
cr：CR（consistent read，一致性讀）讀的數量
cu：在當前模式（current mode）下讀的數量
mis：cursor在快取中錯過的數量
r：涉及的記錄數量
dep：遞迴呼叫深度（0 = user SQL，>0 =recursive）
og：優化器模式：1=All_Rows,2=First_Rows,3=Rule,4=Choose
tim：時間戳，用於確定兩個操作之間的時間

--------------------------------------------------------------------------
ERROR #%d:err=%d tim=%lu
--------------------------------------------------------------------------
一個execution或者tetch錯誤後的錯誤展示
err：在堆疊頂的Oracle錯誤碼（例如：ORA-XXXX）
tim：時間戳

--------------------------------------------------------------------------
STAT #<CURSOR> id=N cnt=0 [pid=0 pos=0 obj=0 op='SORT AGGREGATE ']
--------------------------------------------------------------------------
STAT：為<CURSOR>的執行計劃統計報告
<CURSOR>：統計應用到的Cursor
id：執行計劃中個操作在執行計劃樹中的編號
cnt：涉及的行數
pid：這行的父id
pos：在執行計劃中的位置
obj：行的物件id（如果這是一個基本物件）
op：行涉及的操作

--------------------------------------------------------------------------
XCTEND rlbk=%d rd_only=%d
--------------------------------------------------------------------------
XCTEND：事務結束標誌
rlbk：1表示rollback，0表示commit
rd_only：事務只讀則是1，寫則是0

注：下面的只有當WAITS或者BINDS出現時才存在

--------------------------------------------------------------------------
BINDS #%d:
bind 0: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=03 oacfl2=0 size=24offset=0
bfp=02fedb44 bln=22 avl=00 flg=05
value=10
--------------------------------------------------------------------------
BIND：遊標繫結變數

bind N：繫結變數位置
dty：資料型別
mxl：繫結變數最大長度
mal：陣列長度
scl：規模（Scale）
pre：進度（precision）
oacflg：表明繫結選項的特定標誌
oacfl2：oacflg的延續
size：為這塊分配的記憶體
offset：為這個繫結快取進入這塊的偏移量

bfp：繫結地址
bln：繫結快取長度
avl：實際值長度（也是陣列長度）
flg：表明繫結狀態的特定標誌
value：繫結變數的實際值

--------------------------------------------------------------------------
WAIT #<CURSOR>: nam="" ela=0 p1=0 p2=0 p3=0
--------------------------------------------------------------------------
WAIT：等待事件資訊
nam：等待事件名稱
ela：操作花費的時間
p1：為等待事件提供的引數p1
p2：為等待事件提供的引數p2
p3：為等待事件提供的引數p3

Example (Full Table Scan):
WAIT #1: nam="db file scattered read" ela= 5 p1=4 p2=1435 p3=25
WAITing under CURSOR no 1
for "db file scattered read"
解讀：我們等待0.05秒。為一個讀：檔案4，開始塊1435，共25塊

Example (Index Scan):
WAIT #1: nam="db file sequential read" ela= 4 p1=4 p2=1224 p3=1
WAITing under CURSOR no 1
for "db file sequential read"
解讀：我們等待0.04秒，為單塊讀（p3=1），從檔案4，開始塊1224

 參見：

http://www.2cto.com/database/201408/326439.html