Systemstate Dump分析經(jīng)典案例（上）

前言

本期我們邀請中亦科技的另外一位Oracle專家老K來給大家分享systemstate dump分析的經(jīng)典案例。后續(xù)我們還會有更多技術(shù)專家?guī)砀嗾\意分享。

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

精彩預(yù)告

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

• 如何分析library cache lock？

• 如何分析解讀systemstate dump？

• 如何快速應(yīng)急處理以及收集信息？

溫馨提示

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

Systemstate Dump我們暫且叫SSD吧

Part 1

問題來了

一個(gè)周末的早上，客戶來電，兩節(jié)點(diǎn)RAC數(shù)據(jù)庫其中一個(gè)節(jié)點(diǎn)夯死。

現(xiàn)象描述：

>> 節(jié)點(diǎn)hang死，SYS和普通用戶均無法登陸

>> 受影響范圍只在其中一個(gè)節(jié)點(diǎn)，其他節(jié)點(diǎn)能正常對外提供服務(wù)

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

Part 2

故障處理及信息收集

老K第一反應(yīng)是讓客戶快速收集數(shù)據(jù)庫hanganalyze 和SSD，馬上通過殺進(jìn)程的方式重啟問題節(jié)點(diǎn)數(shù)據(jù)庫，優(yōu)先恢復(fù)數(shù)據(jù)庫服務(wù)。

最終，客戶在收集完信息發(fā)給老K后，重啟了問題節(jié)點(diǎn)數(shù)據(jù)庫，一切又恢復(fù)了正常。

Part 3

知識點(diǎn)掃盲

cursor:pin S wait on X

什么時(shí)候會產(chǎn)生這個(gè)等待事件？

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

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

如何定位其等待的對象？

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

如何查找該事件的源頭？

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

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

library cache lock

什么時(shí)候會產(chǎn)生這個(gè)等待事件？

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

舉一個(gè)簡單的例子，一個(gè)會話（SESSION_A）正在對表TAB_A進(jìn)行DDL操作，另一會話（SESSION_B）開始執(zhí)行與TAB_A相關(guān)的sql語句，那么此時(shí)SESSION_B此時(shí)會等待library cache lock事件。

如何定位其等待的對象？

該等待事件的P1為handle address即為等待對象在library cache 中的句柄地址，可唯一標(biāo)示該內(nèi)存對象。

如何產(chǎn)生該事件的源頭？

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

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

那么數(shù)據(jù)庫異常時(shí)間內(nèi)到底發(fā)生了什么，我們通過trace入手，還原現(xiàn)場。

Part 4

故障分析

環(huán)境介紹：

操作系統(tǒng) AIX 5.3

數(shù)據(jù)庫 ORACLE 10.2.0.5 兩節(jié)點(diǎn)RAC

4.1 第一次頭腦風(fēng)暴

現(xiàn)有“情報(bào)”

>> RAC系統(tǒng)一個(gè)節(jié)點(diǎn)夯

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

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

這兩個(gè)等待事件的原理是什么？

出現(xiàn)上述等待事件后系統(tǒng)的表現(xiàn)是什么？

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

4.2 入手分析

4.2.1

SSD入手分析

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

看起來問題比老K開始想象的要復(fù)雜，但是沒有關(guān)系，以老K處理各種問題的經(jīng)驗(yàn)來看，復(fù)雜問題只不過是多個(gè)簡單問題的集合而已，需要的只是多一點(diǎn)耐心。

接下來，老K做的就是找到這些cursor對象mutex的持有者，以82d61778為例，選取其中一個(gè)正在等待這個(gè)對象的會話（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會話的等待也持續(xù)了非常長的時(shí)間了；同樣的方法，我們再來看看858會話請求的mutex又被誰持有了：

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

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

4.3.2

第二次頭腦風(fēng)暴

>> 會話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的阻塞者是誰，很有可能是一個(gè)“元兇之一”

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

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

4.3.3

繼續(xù)分析SSD

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

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

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

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

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

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

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