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

前言

接上一期：（上一期的閱讀方法：關(guān)注“中亦安圖”公眾號后回復(fù)‘007’）

4.3.4

SSD中l(wèi)ibrary cache lock的分析

接上一期：

分析到這步，前邊看似毫無頭緒的問題似乎理清了，大量cursor:pin S wait on X已經(jīng)理清楚，所有的矛頭走指向了sid 859

離真相只差一步了，我們只需要分析library cache lock的源頭就能解釋整個謎團了，前面老K已經(jīng)提到了分析library cache lock等待事件的方法了，現(xiàn)在我們就來結(jié)合trace文件看看如何定位library cache lock的阻塞關(guān)系。

那好，我們就來看sid 859：

這個會話信息中我們能看到：

>> 會話在等待library cache lock等待事件，等待時間4429秒

>> 會話以S模式請求句柄為700000209bb9d80的library cache對象（request=S）

>> 句柄為700000209bb9d80的library cache對象是SYS.C_OBJ#_INTCOL#，是一個cluster（簇聚）對象。

我們就看到，會話859正在以S模式請求700000209bb9d80上的library cache lock而產(chǎn)生了等待，那么我們就可以確認(rèn)系統(tǒng)中一定有另一個會話以X模式持有了700000209bb9d80上的library cache lock；同樣，我們在trace文件中搜索關(guān)鍵字”700000209bb9d80”再過濾后能看到下面的條目：

我們定位到該條信息后，再確認(rèn)該條信息所屬的會話，確認(rèn)其會話信息如下：

看到這里，大家有沒有柳暗花明的感覺呢，我們看到持有700000209bb9d80上library cache lock的會話是624，而會話624正在等待”cursor:pin S wait on X”事件，等待的對象正是bbcee4f7；現(xiàn)在我們再來完善上面的等待鏈圖：

到最后，我們發(fā)現(xiàn)在會話859和會話624之間，形成了死鎖，具體的情況就是：

>> 會話859持有bbcee4f7上的mutex，請求700000209bb9d80上的library cache lock

>> 會話624持有700000209bb9d80上的library cache lock，請求bbcee4f7上的mutex

>> 其他會話產(chǎn)生大量的cursor:pin S wait on X等待事件，都是由于859長時間持有bbcee4f7上的mutex未釋放導(dǎo)致的

到了這一步，是不是一切謎團都解開了？我們的分析是不是就完成了呢？

↓

↓

↓

↓

↓

↓

答案是：NO

Part 5

根因分析

5.1 第三次頭腦風(fēng)暴

經(jīng)常做根因分析的老K此時還有疑惑：

>> 如果當(dāng)時不重啟，而kill掉死鎖鏈上的會話，問題是否會解決？

>> 會話859和會話624都在做什么，為什么會死鎖？

>> 單個會話持有一個cursor的mutex，怎么會讓系統(tǒng)處于夯住的狀態(tài)？

5.2 柳暗花明之會話859

現(xiàn)在老K重點關(guān)注的就是如何解開上面的兩個疑惑了，繼續(xù)分析trace。

先看會話859，截取trace文件中的信息，如下：

從標(biāo)黃處的信息我們知道，這是一個數(shù)據(jù)庫的后臺進程；我們可以通過查看trace中這個會話所屬的進程信息如下：

先回答第二個問題：會話859在做什么？

后臺進程是CJQ0，這個進程是ORACLE用來調(diào)度job的；我們知道，如果某個會話以S模式請求某個對象上的library cache lock，這個會話通常是在解析某個語句或者編譯某個package時需要從library cache中查找該語句涉及對象的信息；在PROCESS 24的trace文件中查找“oper EXCL”關(guān)鍵字，我們查到以下三條記錄：

在PROCESS 24的trace文件中查找“oper EXCL”關(guān)鍵字，我們查到以下三條記錄： 

Mutex 7000001e7d04898(859, 0) idn bbcee4f7 oper EXCL

Mutex 7000001e5fbe4e0(859, 0) idn fb52493f oper EXCL

Mutex 7000001e8faa990(859, 0) idn a8bbc174 oper EXCL

可能有人會問？一個會話怎么同時有三個cursor？

大家不要忘了ORACLE數(shù)據(jù)庫中有遞歸調(diào)用的說法，也就是說前端發(fā)起一條簡單的sql，ORACLE后臺實際上產(chǎn)生了一系列的遞歸調(diào)用，那些調(diào)用實際上也是一些sql的集合。通過idn值繼續(xù)查找，提煉一下，當(dāng)前正在解析的三條sql語句分別是：

這里說明一下：其實，SSD中對sql的遞歸調(diào)用關(guān)系是不體現(xiàn)的，不過從上面的三條sql語句老K還是能推斷出其調(diào)用關(guān)系的；

CJQ0進程是用來調(diào)度oracle job的，從三條語句能大致的看到：a8bbc174是用來查詢系統(tǒng)中job相關(guān)信息的sql， fb52493f是通過對象號用來查詢某個對象的信息的sql，而bbcee4f7則是用來查詢直方圖信息的sql。

a8bbc174調(diào)用fb52493f，fb52493f調(diào)用bbcee4f7，如果這是bbcee4f7出問題，另外兩個肯定無法正常執(zhí)行。這里正是因為bbcee4f7無法完成解析，而導(dǎo)致其上層的fb52493f和a8bbc174阻塞；

新的疑點：三條SQL和C_OBJ#_INTCOL#有什么內(nèi)在聯(lián)系？

會話正在請求C_OBJ#_INTCOL#上的library cache lock而產(chǎn)生等待，而從這三條sql的文本來看，似乎都跟C_OBJ#_INTCOL#這個對象扯不上關(guān)系，這又怎么解釋呢？有細心的讀者可能已經(jīng)注意到了，前面老K特意指出了C_OBJ#_INTCOL#是一個cluster（簇聚）對象，cluster對象不是表，而是用來存儲多個表的共同列的，那這里我們就可以注意最底層調(diào)用的sql中的histgrm$對象是否與C_OBJ#_INTCOL#有關(guān)，我們來看看histgm$的定義：

又解開了一個謎題，histgrm$確實使用了C_OBJ#_INTCOL#這個cluster對象，所以在解析使用了histgrm$表的sql語句時，需要獲取C_OBJ#_INTCOL#上的library cache lock。

5.3 柳暗花明之會話624

接下來，再來看看會話624，像分析會話859一樣，把單個進程的trace摘出來，我們來截取部分信息如下：

從這里看，這是一個被調(diào)起的job進程，PROCESS號為42；

這不是一個數(shù)據(jù)庫的后臺進程，所以，相比于之前看到的859進程，我們能看到更多的信息，我們大致知道，這個進程是數(shù)據(jù)庫調(diào)起的收集統(tǒng)計信息的job任務(wù)，在等待”cursor:pin S wait on X”事件，等待的解析對象是bbcee4f7；

因為它以X模式持有C_OBJ#_INTCOL#這個對象的library cache lock而阻塞了關(guān)鍵的會話859，那么我們來看看它為什么會持有這個library cache lock；我們到PROCESS 42的進程信息中搜索oper EXCL的關(guān)鍵字，搜索到兩條相關(guān)信息如下：

同樣，我們也能從sql語句的語義上猜到兩者的遞歸調(diào)用關(guān)系；

會話624持有了C_OBJ#_INTCOL#和I_OBJ#_INTCOL#的library cache lock，其中I_OBJ#_INTCOL#是CLUSTER的索引?，F(xiàn)在所有疑團都解開了。可以放松一下，從頭捋順?biāo)悸妨恕?/p>

Part 6

情景再現(xiàn)

終于看到了全景，看看數(shù)據(jù)庫故障時刻在做什么。

在本場景中，t1時刻，數(shù)據(jù)庫自動收集統(tǒng)計信息任務(wù)調(diào)度J000進程收集整個數(shù)據(jù)庫統(tǒng)計信息，在收集cluster對象時，數(shù)據(jù)庫只能使用analyze的方式分析；

t2時刻，因為C_OBJ#_INTCOL#對象的統(tǒng)計信息被更新，因為histgrm$與C_OBJ#_INTCOL#的關(guān)聯(lián)關(guān)系，與histgrm$相關(guān)的sql（包括bbcee4f7）也就需要重新解析；

t3時刻，J000先收集C_OBJ#_INTCOL#統(tǒng)計信息，接著繼續(xù)使用analyze的方式收集其索引I_OBJ#_INTCOL#的統(tǒng)計信息；

t4時刻，這時CJQ0進程定時查詢系統(tǒng)JOB時，需要硬解析，遞歸調(diào)用bbcee4f7時對其進行解析；

解析的過程中需要以S模式請求持有histgrm$及其相關(guān)對象（也就包括C_OBJ#_INTCOL#及其索引I_OBJ#_INTCOL#）的library cache lock；

t4時刻，J000進程正在analyze索引I_OBJ#_INTCOL#，也就以X模式持有了I_OBJ#_INTCOL#上的library cache lock；

在J000使用analyze的過程中，同樣需要執(zhí)行相關(guān)遞歸sql，需要進行硬解析，也就調(diào)用了上面說到的關(guān)鍵sql bbcee4f7；

所以最后造成了死鎖。

Part 7

問題定位

其實在上述分析的過程中，我們基本可以判斷為bug，（MOS）:1628214.1 Database Appears to Hang with Deadlock Involving SYS.C_COBJ# or C_OBJ#_INTCOL# While Statistics Maintenance Job is Running

Part 8

寫在最后

到上面為止，我們已經(jīng)定位bug，也獲得了事中和事后的解決方案，不過老K更關(guān)注的是大家是否能從這個CASE中獲得一些收獲，這里不妨問問自己：

>> Systemstatedump中的cursor:pin S wait on X 我會查了嗎？

>> Systemstatedump中的library cache lock 我會查了嗎？

>> 如果我要模擬讓我的數(shù)據(jù)庫夯我會做嗎？

>> 還有一個沒有回答的問題？如果下次再遇到同樣的問題，我能通過殺掉死鎖鏈條里的進程解決這個問題么？

如果你的答案都是肯定的，那么老K覺得這篇分享很有價值。

如果以上問題你還有疑問，可以通過微信或者QQ共同交流討論。