Systemstate Dump分析經典案例（上）

前言

本期我們邀請中亦科技的另外一位Oracle專家老K來給大家分享systemstate dump分析的經典案例。后續我們還會有更多技術專家帶來更多誠意分享。

老K作為一個長期在數據中心奮戰的數據庫工程師，看到小y前期的分享，有種躍躍欲試的感覺，也想把我日常遇到的一些有意思的案例拿出來分享討論，希望我們都能從中獲得些許收獲，少走彎路。同時本文涉及到很多基礎知識，又涉及看似枯燥的trace分析，但老K還是建議大家耐心看完本文。

精彩預告

• 如何分析cursor:pin S wait on X？

• 如何分析library cache lock？

• 如何分析解讀systemstate dump？

• 如何快速應急處理以及收集信息？

溫馨提示

溫馨提示：該篇為老K誠意之作，篇幅略長，如微信閱讀有所不適，可以移步QQ群：227189100下載文本閱讀，并同時關注我們的微信號“中亦安圖”與我們交流。

Systemstate Dump我們暫且叫SSD吧

Part 1

問題來了

一個周末的早上，客戶來電，兩節點RAC數據庫其中一個節點夯死。

現象描述：

>> 節點hang死，SYS和普通用戶均無法登陸

>> 受影響范圍只在其中一個節點，其他節點能正常對外提供服務

>> hang死節點有大量異常等待事件cursor:pin S wait on X以及少量library cache lock。

Part 2

故障處理及信息收集

老K第一反應是讓客戶快速收集數據庫hanganalyze 和SSD，馬上通過殺進程的方式重啟問題節點數據庫，優先恢復數據庫服務。

最終，客戶在收集完信息發給老K后，重啟了問題節點數據庫，一切又恢復了正常。

Part 3

知識點掃盲

cursor:pin S wait on X

什么時候會產生這個等待事件？

當一個會話以X模式持有某個cursor（如sql/procedure/function/package body等）的mutex時，如果另一個會話需要以S模式請求該cursor的mutex；一般來說，對cursor進行硬解析時，會以X模式持有cursor的mutex，而對cursor進行軟解析時，則會以S模式持有cursor的mutex；

舉一個簡單的例子，一個會話（SESSION_A）正在解析（硬解析）某一個sql語句（SQL_A），當另一個會話（SESSION_B）同時執行這條sql語句（SQL_A）時（執行前需要對該語句進行軟解析），SESSION_B就會等待cursor:pin S wait on X 事件。

如何定位其等待的對象？

該等待事件的P1參數idn，實際上就是sql語句的hash_value，也就是說通過該等待事件的P1參數即可定位等待的實際對象。

如何查找該事件的源頭？

在定位了該等待事件所等待的對象后，該對象MUTEX的持有者即為該等待事件的源頭。

在trace文件中，可以通過oper EXCL關鍵字查找到持有者。

library cache lock

什么時候會產生這個等待事件？

當一個會話對library cache中的對象（主要是TABLE /INDEX/CLUSTER/PROCEDURE等）進行修改（通常是指DDL操作）時，會以X模式持有該對象的library cache lock；當一個會話在解析sql需要用到某個對象時，會以S模式請求該對象的library cache lock；

舉一個簡單的例子，一個會話（SESSION_A）正在對表TAB_A進行DDL操作，另一會話（SESSION_B）開始執行與TAB_A相關的sql語句，那么此時SESSION_B此時會等待library cache lock事件。

如何定位其等待的對象？

該等待事件的P1為handle address即為等待對象在library cache 中的句柄地址，可唯一標示該內存對象。

如何產生該事件的源頭？

在定位了該等待事件所等待的對象后，持有該對象的X模式library cache lock的會話即為等待事件的源頭。

在trace文件中，可以通過對象的地址關鍵字和mode=X關鍵字查找到該等待事件的源頭。

那么數據庫異常時間內到底發生了什么，我們通過trace入手，還原現場。

Part 4

故障分析

環境介紹：

操作系統 AIX 5.3

數據庫 ORACLE 10.2.0.5 兩節點RAC

4.1 第一次頭腦風暴

現有“情報”

>> RAC系統一個節點夯

>> 數據庫中存在大量cursor:pin S wait on X 等待事件和少量library cache lock等待事件

>> 有收集的hanganalyze 信息和SSD  trace文件

這兩個等待事件的原理是什么？

出現上述等待事件后系統的表現是什么？

當一個系統出現大量cursor:pin S wait on X 等待事件時，通常原因是由于一個會話的sql硬解析異常，阻塞了這條SQL的軟解析，這種情況下，可能的源頭就只有一個，只要把源頭找到，問題就迎刃而解了。

4.2 入手分析

4.2.1

SSD入手分析

出乎老K的意料，這些等待” cursor:pin S wait on X”的會話并不都在同一個idn上，而是分布在幾個不同的idn上。

看起來問題比老K開始想象的要復雜，但是沒有關系，以老K處理各種問題的經驗來看，復雜問題只不過是多個簡單問題的集合而已，需要的只是多一點耐心。

接下來，老K做的就是找到這些cursor對象mutex的持有者，以82d61778為例，選取其中一個正在等待這個對象的會話（sid:598）來分析，見下圖

這里需要解釋一下

idn 82d61778：表明cursor對象

oper GET_SHRD：表明該會話正在以shared模式請求該mutex

(858, 0)：表明該mutex的持有者sid為858

找到了持有者，我們接著來看看sid為858的會話（858會話）在做什么：

上圖可以看出858會話也在等待”cursor:pin S wait on X”，而且從等待歷史看，858會話的等待也持續了非常長的時間了；同樣的方法，我們再來看看858會話請求的mutex又被誰持有了：

我們看到了會話859持有了bbcee4f7的mutex，然后它又在等待”library cache lock”事件。

問題查到這，我們停下來想一想。

4.3.2

第二次頭腦風暴

>> 會話598在等待cursor:pin S wait on X，阻塞者sid為 858

>> 會話858在等待cursor:pin S wait on X事件，阻塞者sid為859

>> 會話859在等待library cache lock事件，阻塞者待查

>> library cache lock的阻塞者是誰，很有可能是一個“元兇之一”

>>是不是大量的cursor:pin S wait on X都被library cache lock阻塞，如果是的話問題就變得簡單了

如果看到這里你還暈暈的，那么老K建議讀者不妨拿出筆畫個圖，我們就暫且稱之為等待鏈圖吧：

4.3.3

繼續分析SSD

這里我們暫且先不查“首要嫌疑人”，而是繼續梳理等待事件關系，同上分析方法，我們找到trace中各IDN對象的持有者信息，如下：

我們看到，859/858/815等會話目前持有mutex，并且阻塞了其他會話以shared模式獲取其持有的mutex；其中859會話為我們剛剛找的等待鏈的源頭，858會話為我們剛剛找到的等待鏈的中間部分，作為一個mutex的持有者，同時又在等待另一個mutex，那我們再來看看其他會話都在等什么：

老K這里就不把上述所有會話的信息都列出來了，經過確認，各會話的均是在等待”cursor:pin S wait on X”等待事件，這時，我們再來更新一下我們的等待鏈圖：

分析到了這里是不是已經柳暗花明了？前面理不清的大量cursor:pin S wait on X已經理清楚，所有的矛頭走指向了sid 859

離真相只差一步了，我們只需要分析library cache lock的源頭就能解釋整個謎團了，前面老K已經提到了分析library cache lock等待事件的方法了，

下一步只要結合trace文件定位library cache lock的阻塞關系，就能很快定位原因了。

由于篇幅有限，本期分享到這里先告一段落，下期分享繼續，看老K如何一步一步由淺入深，分析問題，看看高大上的SSD分析是什么樣的。敬請關注下期（未完待續...）