第一章 技術人生系列 · 我和資料中心的故事（第八期）Systemstate Dump分析經典案例（下）

中亦安圖 | 2016-03-08 21:45

前言

接上一期：（上一期的閱讀方法：關注“中亦安圖”公眾號後回覆‘007’）

4.3.4

SSD中library cache lock的分析

接上一期：

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

離真相只差一步了，我們只需要分析library cache lock的源頭就能解釋整個謎團了，前面老K已經提到了分析library cache lock等待事件的方法了，現在我們就來結合trace檔案看看如何定位library cache lock的阻塞關係。

那好，我們就來看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而產生了等待，那麼我們就可以確認系統中一定有另一個會話以X模式持有了700000209bb9d80上的library cache lock；同樣，我們在trace檔案中搜尋關鍵字”700000209bb9d80”再過濾後能看到下面的條目：

我們定位到該條資訊後，再確認該條資訊所屬的會話，確認其會話資訊如下：

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

到最後，我們發現在會話859和會話624之間，形成了死鎖，具體的情況就是：

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

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

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

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

↓

↓

↓

↓

↓

↓

答案是：NO

Part 5

根因分析

5.1 第三次頭腦風暴

經常做根因分析的老K此時還有疑惑：

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

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

>> 單個會話持有一個cursor的mutex，怎麼會讓系統處於夯住的狀態？

5.2 柳暗花明之會話859

現在老K重點關注的就是如何解開上面的兩個疑惑了，繼續分析trace。

先看會話859，擷取trace檔案中的資訊，如下：

從標黃處的資訊我們知道，這是一個資料庫的後臺程式；我們可以通過檢視trace中這個會話所屬的程式資訊如下：

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

後臺程式是CJQ0，這個程式是ORACLE用來排程job的；我們知道，如果某個會話以S模式請求某個物件上的library cache lock，這個會話通常是在解析某個語句或者編譯某個package時需要從library cache中查詢該語句涉及物件的資訊；在PROCESS 24的trace檔案中查詢“oper EXCL”關鍵字，我們查到以下三條記錄：

在PROCESS 24的trace檔案中查詢“oper EXCL”關鍵字，我們查到以下三條記錄：

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資料庫中有遞迴呼叫的說法，也就是說前端發起一條簡單的sql，ORACLE後臺實際上產生了一系列的遞迴呼叫，那些呼叫實際上也是一些sql的集合。通過idn值繼續查詢，提煉一下，當前正在解析的三條sql語句分別是：

這裡說明一下：其實，SSD中對sql的遞迴呼叫關係是不體現的，不過從上面的三條sql語句老K還是能推斷出其呼叫關係的；

CJQ0程式是用來排程oracle job的，從三條語句能大致的看到：a8bbc174是用來查詢系統中job相關資訊的sql， fb52493f是通過物件號用來查詢某個物件的資訊的sql，而bbcee4f7則是用來查詢直方圖資訊的sql。

a8bbc174呼叫fb52493f，fb52493f呼叫bbcee4f7，如果這是bbcee4f7出問題，另外兩個肯定無法正常執行。這裡正是因為bbcee4f7無法完成解析，而導致其上層的fb52493f和a8bbc174阻塞；

新的疑點：三條SQL和C_OBJ#_INTCOL#有什麼內在聯絡？

會話正在請求C_OBJ#_INTCOL#上的library cache lock而產生等待，而從這三條sql的文字來看，似乎都跟C_OBJ#_INTCOL#這個物件扯不上關係，這又怎麼解釋呢？有細心的讀者可能已經注意到了，前面老K特意指出了C_OBJ#_INTCOL#是一個cluster（簇聚）物件，cluster物件不是表，而是用來儲存多個表的共同列的，那這裡我們就可以注意最底層呼叫的sql中的histgrm$物件是否與C_OBJ#_INTCOL#有關，我們來看看histgm$的定義：

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

5.3 柳暗花明之會話624

接下來，再來看看會話624，像分析會話859一樣，把單個程式的trace摘出來，我們來擷取部分資訊如下：

從這裡看，這是一個被調起的job程式，PROCESS號為42；

這不是一個資料庫的後臺程式，所以，相比於之前看到的859程式，我們能看到更多的資訊，我們大致知道，這個程式是資料庫調起的收集統計資訊的job任務，在等待”cursor:pin S wait on X”事件，等待的解析物件是bbcee4f7；

因為它以X模式持有C_OBJ#_INTCOL#這個物件的library cache lock而阻塞了關鍵的會話859，那麼我們來看看它為什麼會持有這個library cache lock；我們到PROCESS 42的程式資訊中搜尋oper EXCL的關鍵字，搜尋到兩條相關資訊如下：

同樣，我們也能從sql語句的語義上猜到兩者的遞迴呼叫關係；

會話624持有了C_OBJ#_INTCOL#和I_OBJ#_INTCOL#的library cache lock，其中I_OBJ#_INTCOL#是CLUSTER的索引。現在所有疑團都解開了。可以放鬆一下，從頭捋順思路了。

Part 6

情景再現

終於看到了全景，看看資料庫故障時刻在做什麼。

在本場景中，t1時刻，資料庫自動收集統計資訊任務排程J000程式收集整個資料庫統計資訊，在收集cluster物件時，資料庫只能使用analyze的方式分析；

t2時刻，因為C_OBJ#_INTCOL#物件的統計資訊被更新，因為histgrm$與C_OBJ#_INTCOL#的關聯關係，與histgrm$相關的sql（包括bbcee4f7）也就需要重新解析；

t3時刻，J000先收集C_OBJ#_INTCOL#統計資訊，接著繼續使用analyze的方式收集其索引I_OBJ#_INTCOL#的統計資訊；

t4時刻，這時CJQ0程式定時查詢系統JOB時，需要硬解析，遞迴呼叫bbcee4f7時對其進行解析；

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

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

在J000使用analyze的過程中，同樣需要執行相關遞迴sql，需要進行硬解析，也就呼叫了上面說到的關鍵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

寫在最後

到上面為止，我們已經定位bug，也獲得了事中和事後的解決方案，不過老K更關注的是大家是否能從這個CASE中獲得一些收穫，這裡不妨問問自己：

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

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

>> 如果我要模擬讓我的資料庫夯我會做嗎？

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

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

About Me

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

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

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

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

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

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

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