System State 轉儲分析案例一則

Oracle | 2016-02-05 08:37

在 Oracle 資料庫的執行過程中，可能會因為一些異常遇到資料庫掛起失去響應的狀況，在這種狀況下，我們可以通過對系統狀態進行轉儲，獲得跟蹤檔案進行資料庫問題分析；很多時候資料庫也會自動轉儲出現問題的程式或系統資訊；這些轉儲資訊成為我們分析故障、排查問題的重要依據。

本章通過實際案例的詳細分析，講解如何逐層入手、層層剖析的分析資料庫故障。

1.1 狀態轉儲的常用命令

當資料庫出現一些掛起狀態時，往往會嚴重影響到資料庫使用，程式級的問題影響範圍較小，而系統級的問題則會影響全域性。

在出現資料庫系統或程式失去響應時，如果 SQL*Plus 工具仍然可以連線，可能檢視查詢沒有相應，但是可以通過 oradebug 工具來進行程式及系統狀態資訊的轉儲，從而可以進行 Hang 分析。

DUMP 程式狀態可以使用：

alter sessions set events'immediate trace name processstate level '；

或者使用：

oradebug setmypid

oradebug ulimit

oradebug dumpprocessstate

當診斷資料庫掛起時，可以使用 DUMP 命令轉儲整個系統狀態：

altersessions set events 'immediate trace name systemstate level '；

或：

oradebugsetmypid

oradebugulimit

oradebugdump systemstate

如果為了獲取全面一點的資訊，可以使用 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 轉儲分析案例一則 作者：蓋國強

About Me

....................................................................................................................................................

本文來自於微信公眾號轉載文章，若有侵權，請聯絡小麥苗及時刪除

ITPUB BLOG：http://blog.itpub.net/26736162

QQ：642808185 若加QQ請註明您所正在讀的文章標題

【版權所有，文章允許轉載，但須以連結方式註明源地址，否則追究法律責任】

....................................................................................................................................................

來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/26736162/viewspace-2080714/，如需轉載，請註明出處，否則將追究法律責任。