《DBA必備技能：數據庫掛起時進行轉儲分析診斷案例》要點：
本文介紹了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 數據庫的的等待事件以及內部工作原理.

文章來自微信公眾號：數據和云

轉載請注明本頁網址：
http://www.snjht.com/jiaocheng/2392.html