151
DBA必備技能：數據庫掛起時進行轉儲分析診斷案例
在上周末培訓中，有同學問起：如何在數據庫掛起時進行診斷和分析？這裏就是這樣一個案例。分析、深入，解數據庫之疑難。
在 Oracle 數據庫的運行過程中，可能會因為一些異常遇到數據庫掛起失去響應的狀況，在這種狀況下，我們可以通過對係統狀態進行轉儲，獲得跟蹤文件進行數據庫問題分析；很多時候數據庫也會自動轉儲出現問題的進程或係統信息；這些轉儲信息成為我們分析故障、排查問題的重要依據。
本章通過實際案例的詳細分析，講解如何逐層入手、層層剖析的分析數據庫故障。
1.1 狀態轉儲的常用命令
當數據庫出現一些掛起狀態時，往往會嚴重影響到數據庫使用，進程級的問題影響範圍較小，而係統級的問題則會影響全局。
在出現數據庫係統或進程失去響應時，如果 SQL*Plus 工具仍然可以連接，可能視圖查詢沒有相應，但是可以通過 oradebug 工具來進行進程及係統狀態信息的轉儲，從而可以進行 Hang 分析。
DUMP 進程狀態可以使用：
alter sessions set events'immediate trace name processstate level <level>'；
或者使用：
oradebug setmypid
oradebug ulimit
oradebug dumpprocessstate<level>
當診斷數據庫掛起時，可以使用 DUMP 命令轉儲整個係統狀態：
altersessions set events 'immediate trace name systemstate level <level>'；
或：
oradebugsetmypid
oradebugulimit
oradebugdump systemstate <level>
如果為了獲取全麵一點的信息，可以使用 Level 10。
SQL> oradebug setmypid
SQL> oradebug unlimit
SQL> oradebug dump systemstate 10
另外如果係統掛起，無法用 SQL*Plus 連接，從 Oracle 10g 開始，可以使用 sqlplus -prelim 選項強製登錄，然後即可進行係統狀態信息轉儲：
sqlplus -prelim '/ as sysdba'
oradebug setmypid
oradebug unlimit;
oradebug dump systemstate 10
1.2 WAITED TOO LONG FOR A ROW CACHEENQUEUE LOCK! 案例
在一次客戶現場培訓中，客戶提出一個係統正遇到問題，請求我協助診斷解決，理論聯係實踐，這是我在培訓中極力主張的，我們的案例式培訓業正好遇到了實踐現場。
問題是這樣的：
此前一個 Job 任務可以在秒級完成，而現在運行了數小時也無法結束，一直掛起在數據庫中，殺掉進程重新手工執行，嚐試多次，同樣無法完成。
客戶的數據庫環境為：
Oracle Database 10gEnterprise Edition Release 10.2.0.3.0 - 64bit Production
With thePartitioning, OLAP and Data Mining options
Node name: SF2900 Release: 5.9 Version: Generic_118558-33Machine: sun4u
介入問題診斷首先需要收集數據，我最關注兩方麵的信息：
1． 告警日誌文件，檢查是否出現過異常
2． 生成 AWR 報告，檢查數據庫內部的運行狀況
通常有了這兩部信息，我們就可以做出初步判斷了。
檢查數據庫的告警日誌文件，我們發現其中出現過一個如下錯誤：
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUELOCK! <<<
這個錯誤提示出現在7點左右，正是 JOB 的調度時間附近，顯然這是一個高度相關的可能原因。
1.3 DUMP 轉儲文件分析定位問題
這個異常生成了轉儲的 DUMP 文件，獲得該文件進行進一步的詳細分析。
該文件得頭部信息如下：
ROW CACHE 隊列鎖無法獲得，表明數據庫在 SQL 解析時，遇到問題，DC 層麵出現競爭，導致超時。Row Cache 位於 Shared Pool 中的 Data Dictionary Cache，是用於存儲表列定義、權限等相關信息的。
注意以上信息中的重要內容包括：
1． 超時告警的時間是06:54: 2010-03-27 06:54:00.106
2． 出現等待超時的數據庫進程號是29：Oracle process number: 29
3． 等待超時的29號進程的 OS 進程號為8317：Unix process pid: 8371
4． 進程時通過 SQL*Plus 調度執行的：MODULE NAME:(SQL*Plus)
5． 會話的 ID、Serial# 信息為120.46138：SESSION ID:(120.46138)
6． 進程的 State Object 為 6c10508e8：row cache enqueue: session: 6c10508e8
7． 隊列鎖的請求模式為共享（S）：mode: N, request: S
有了這些重要的信息，我們就可以開始一些基本的分析。
首先可以在跟蹤文件中找到29號進程，查看其中的相關信息。經過檢查可以發現這些內容與跟蹤文件完全相符合：
進一步的向下檢查可以找到 SO 對象 6c10508e8，這裏顯示該進程確實由客戶端的 SQL*Plus 發起，並且客戶端的主機名稱及進程的 OSPID 都記錄在案：
接下來的信息顯示，進程一直在等待，等待事件為 'ksdxexeotherwait'：
在這個進程跟蹤信息的最後部分，有如下一個 SO 對象繼承關係列表，注意這裏的 OWNER 具有級聯關係，下一層隸屬於上一層的 Owner，第一個 SO對象的 Owner 6c1006740 就是 PROCESS 29 的 SO 號。
到了最後一個級別的 SO 4e86f03e8上，請求出現阻塞。
Row cache enqueue 有一個（count=1）共享模式（request=S）的請求被阻塞：
回過頭去對比一下跟蹤文件最初的信息，注意這裏的 session 信息正是跟蹤文件頭上列出的 session 信息：
至此我們找到了出現問題的根源，這裏也顯示請求的對象是 object=4f4e57138。
1.4 ROW CACHE 對象的定位
跟蹤文件向下顯示了更進一步的信息，地址為 4f4e57138 的 Row Cache Parent Object 緊跟著之前的信息顯示出來，跟蹤信息同時顯示是在 DC_OBJECTS 層麵出現的問題。
跟蹤信息顯示對象的鎖定模式為排他鎖定（mode=X）。
下圖是跟蹤文件的截取，我們可以看到 Oracle 的記錄方式：
進一步的，跟蹤文件裏也顯示了29號進程執行的 SQL為INSERT 操作：
好了，那麼現在我們來看看是哪一個進程排他的鎖定了之前的4f4e57138對象。在跟蹤文件中搜索4f4e57138就可以很容易的找到這個持有排他鎖定的 SO 對象。
以下顯示了相關信息，Row Cache 對象的信息在此同樣有所顯示：
再向上找到這個進程的信息，發現其進程號為16：
在這裏可以看到16號進程是一個 JOB 進程，其進程為J000，那麼這個 JOB 進程在執行什麼操作呢？下麵的信息可以看出一些端倪，JOB 由 DBMS_SCHEDULER 調度，執行 AUTO_SPACE_ADVISOR_JOB 任務，處於 Wait for shrink lock 等待：
進一步向下查找，可以找到 Shrink 操作執行的 SQL 語句：
至此，真相大白於天下：
1． 係統通過 DBMS_SCHEDULER 調度執行 AUTO_SPACE_ADVISOR_JOB 任務
發出了 SQL 語句：
alter index"CACI"."IDX_CACI_INV_BLB_DC" modify partition"P_2010_Q1" shrink space CHECK
2． 定時任務不能及時完成產生了排他鎖定
3． 客戶端執行的 INSERT 操作掛起
INSERT 語句為：
INSERT /*+ APPEND*/ INTOCACI_INV_BLB_DC NOLOGGING SELECT :B1 , T.*, SYSDATE FROM CACI_INV_BLB T
Shrink Space 的語句所以不能成功完成是因為該索引的相關數據表的數據量過為巨大。在 Oracle10g 中，缺省的有一個任務定時進行分析為用戶提供空間管理建議，在進行空間建議前，Oracle 執行 Shrink Space Check，這個檢查工作和 Shrink 的具體內部工作完全相同，隻是不執行具體動作。
這個 Shrink Space 的檢查對於客戶環境顯得多餘。
現場解決這個問題，隻需要將16號進程 Kill 掉，即可釋放了鎖定，後麵的操作可以順利進行下去。
1.5 使用 ass109.awk 腳本輔助分析
對於類似的跟蹤文件，可以通過 Oracle 提供的 ass109.awk 腳本來分析，分析之後可以獲得簡明的輸出（我的 Windows 上做了 Unix 工具增強，可以直接運行 awk 工具進行分析）：
D:\>awk -f ass109.awk edw_ora_8371.trc
..........................
Ass.Awk Version 1.0.9 - Processingedw_ora_8371.trc
System State 1
~~~~~~~~~~~~~~~~
1:
2: waiting for 'rdbms ipc message' wait
3: waiting for 'pmon timer' wait
4: waiting for 'rdbms ipc message' wait
5: waiting for 'rdbms ipc message' wait
6: waiting for 'rdbms ipc message' wait
7: waiting for 'rdbms ipc message' wait
8:
9: waiting for 'rdbms ipc message' wait
10:
11: waiting for 'rdbms ipc message' wait
12: for 'Streams AQ: waiting for timemanagement or cleanup tasks' wait
13: waiting for 'rdbms ipc message' wait
14: waiting for 'Streams AQ: qmncoordinator idle wait' wait
15: waiting for 'rdbms ipc message' wait
16:waiting for 'Wait for shrink lock' wait
17: waiting for 'smon timer' wait
18: waiting for 'SQL*Net message fromclient' wait
19: waiting for 'rdbms ipc message' wait
21: waiting for 'rdbms ipc message' wait
23: waiting for 'rdbms ipc message' wait
25: waiting for 'SQL*Net message fromclient' wait
27: waiting for 'SQL*Net message fromclient' wait
29:last wait for 'ksdxexeotherwait' [Rcache object=4f4e57138,]
Cmd: Insert
30: waiting for 'Streams AQ: qmn slave idlewait' wait
33: for 'Streams AQ: waiting for messagesin the queue' wait
Blockers
~~~~~~~~
Aboveis a list of all the processes. If they are waiting for a resource
thenit will be given in square brackets. Below is a summary of the
waitedupon resources, together with the holder of that resource.
Notes:
~~~~~
o A process id of '???' implies that theholder was not found in the
systemstate.
Resource Holder State
Rcache object=4f4e57138, 16: waiting for 'Wait for shrink lock'
Object Names
~~~~~~~~~~~~
Rcache object=4f4e57138,
77807 Lines Processed.
注意，輸出文件中清晰地指出，數據庫的16號進程持有了對象4f4e57138的 Row Cache 鎖，正在等待：Wait for shrink lock。而29號進程正是在4f4e57138對象上產生了等待，處於掛起狀態，無法執行INSERT操作。
1.6 AWR 報告的輔助診斷
生成數據庫出現問題時段的 AWR 報告，也可以輔助我們確定數據庫的相關操作。在以下圖示中顯示，Top 4SQL 都運行超過3400秒沒有完成，第一個正是任務調度：
相關的 SQL 簡要列舉如下：
calldbms_space.auto_space_advisor_job_proc ( )
alter index"CACI"."IDX_CACI_INV_BLB_DC" modify partition"P_2010_Q1" shrink space CHECK
而如果你不關心空間建議，則可以取消這個定時任務，避免不比要的麻煩：
executedbms_scheduler.disable('AUTO_SPACE_ADVISOR_JOB');
最後還有一點需要額外說明的是，既然是 ROW Cache在DC（DictionaryCache）層麵產生的競爭，那到底是什麼對象呢？如何獲得顯示的證據呢？
我們再來回顧一下 SO 對象的以下部分信息：
這部分 Data 信息是什麼呢？我們稍微逆向的轉換一下。這次動作涉及的 SQL 是：
alter index"CACI"."IDX_CACI_INV_BLB_DC" modify partition"P_2010_Q1" shrink space CHECK
對象是 IDX_CACI_INV_BLB_DC 索引的 P_2010_Q1 分區，使用 dump 函數取一下16進製編碼，獲得如下輸出：
SO 對象的 Data 部分正是指出了需要的對象內容，而當這個對象被排他鎖定後，接下來的訪問就處於了掛起狀態。
這個案例給我們的經驗是：當你使用新的數據庫版本時，一定要認真了解其新特性，確保不會因為新特性而帶來麻煩。
1.7 狀態轉儲的常用命令
在某些情況下，Oracle 數據庫在遇到異常時，會自動轉儲數據庫的係統狀態信息，此時會在告警日誌裏記錄類似如下的信息：
>>> WAITED TOO LONG FOR A ROWCACHE ENQUEUE LOCK! pid=212
System State dumped to trace file/opt/oracle/admin/eygle/udump/eygle_ora_2123.trc
分析這一類的轉儲文件，可以幫助我們快速定位和找到問題的根源。有些時候，在係統出現異常掛起或莫名的性能問題時，也可以通過手工轉儲來獲得係統的狀態信息輸出，幫助我們進行數據庫性能數據收集，進而分析可能的原因。
而通過這樣的 DUMP 文件，輔助我們上一節提到的 ass109.awk 腳本，則可以很容易的同一般用戶進行遠程的診斷和故障處理，以下是一個朋友在係統出現 Hang 住掛起時轉儲的狀態文件分析，通過分析結果我們可以清晰的判斷是歸檔的原因導致了係統出現 Library Cache Lock 和 Buffer Busy Waits 等等待：
通過這個簡單的分析結果，再結合原始跟蹤文件分析，非常有助於我們理解 Oracle 數據庫的的等待事件以及內部工作原理。
文章來源：《Oracle DBA 手記 2》- System State 轉儲分析案例一則 作者：蓋國強
本文出自數據和雲公眾號，原文鏈接
最後更新：2017-07-18 11:03:42