【徵文】cursor: pin S wait on X等待事件的處理過程

 

最近負責的一個10204 for Linux as4的資料庫（64bit），會短暫出現大量cursor: pin S wait on X等待事件，部分操作會被掛起，最長等待時間大概4分鐘，之後則會自行恢復。這個問題困擾了我一週多的時間，從現在的情況上看，我們應該是解決了這個問題。

 

以下則是事件的回放：

7月18日，應用反映17日下午16：56分左右，出現部分介面的呼叫操作無返回，要求協助檢查原因。

要求應用提供資料進行核對，當時確認應用提供的那些需要處理的資料都是正常處理的，處理的時間與呼叫的時間並也無太大出入。

呼叫方設定的超時時間是60秒，60秒後會斷開連線，判斷為無返回。所以可能是延遲超過60秒未返回給呼叫方導致的。由於應用沒有記錄詳細的介面呼叫日誌，不能確定是資料庫返回給應用延遲還是應用返回給呼叫方延遲。

我製作了發生問題的時間點的效能分析報告，可以確認部分sql的執行明顯放緩，等待cursor: pin S wait on X事件，但是平均執行時間也就是1秒左右。應該不致導致應用60秒超時。幾天以後我才意識到由於出現故障的時間很短，而正常情況下平均執行時間都是很短的，我的效能分析報告是1個小時的，但是出現故障的那一兩分鐘，插入記錄的執行效率是非常低的，只是按照小時平均下來就沒有那麼明顯了。

要求應用協助記錄詳細的呼叫及返回時間，便於確認是資料庫的問題還是應用的問題。

 

7月23日左右，偶然發現當時核對的處理的資料都是取自A表的，呼叫該介面會在插入A表後，在B表也插入相應的記錄，但是B表的插入時間則相差很多，也就是基本可以確定是資料庫的延遲返回給應用導致的超時。進行了更詳細的分析發現，A表的插入正常，但是B表在一段時間內沒有插入任何記錄，B表是插入頻率相當高的表，所以這是非常不正常的，應該是被阻塞了。

想起6月29日和7月8日都出現過報警（ORA-03113: end-of-file on communication channel），同一時間點大量的session中斷了和資料庫的連線，查詢了報警時間點的B表記錄，發現了相似的情況，阻塞的時間基本在1分多到2分多之間，但是已經不能得到那兩個時間點的效能分析報告，不能確定當時的等待事件的情況。

出現問題的時間點，有時候是訪問量稍大，有時候則完全是在低谷時，感覺上不應該是猛增的大量呼叫導致的問題。

由於6月29日、7月8日、7月17日出現的頻率很像9-10天一次，所以我估計下一次出現在7月26日左右，並且企圖尋找發生時間上的規律。

 

7月24日23點，又出現類似的現象，這次持續的時間在4分多鐘，是最近幾次發現的最長的一次。

從效能報告上看，仍然是cursor: pin S wait on X等待事件在首位，並發現大量的解析時間，但是解析的次數並沒有變化。作業系統的引數上看，並沒有發現io、cpu或者記憶體的異常。

之前我們一直懷疑是高負載導致的不同session之前的鎖等待，這次可以確定不是由於高負載導致的鎖等待，倒是大量的cursor等待導致了短時間的高負載。

 

這期間查詢了metalink上很多的資料，主要從cursor: pin S wait on X著手處理，metalink上很多cursor: pin S wait on X的類似問題，有的確認是bug，有的是作業系統的問題，有的則因為不能重現就沒了下文，但是並沒有發現和我們完全吻合的情況，而且我們也不能重現這個問題。我們也察看過和mutex機制相關的檢視，例如V$mutex_sleep，但是並沒有得到有價值的資訊。

有人提到是因為存在直方圖，導致過度解析，建議如果不需要則刪除直方圖，他提到的現象中可以看到sql有大量的version count，檢查我們的資料庫，的確自動收集的統計資訊中已經包括直方圖，但是並沒有發現發生過度解析，而且我們的程式編寫是嚴格按照繫結變數呼叫的，不會存在因為sql不繫結變數導致的相關問題。

 

由於出現該等待的時候，資料庫並不會丟擲錯誤，新連線也是可以正常連線的，只有某個表的插入被阻塞，其他表的訪問也都正常。這個等待事件平常也是出現的，只是不會佔用大量的時間。所以我們的報警程式捕獲不到這個問題，只能通過應用得反饋才知道又出現了，而等我們知道發生問題的時候，通常已經恢復正常了。我也一直沒有下決心增加跟蹤事件，因為不確定發生的頻率和時間，擔心跟蹤檔案把磁碟寫滿了。

因為這個表使用的複合分割槽，所以一度讓我懷疑是這個版本的分割槽的bug。這個資料庫在5月份打了最新的10204的補丁，在最初執行的一兩個月裡都沒有出現過類似的情況，而最近應用都沒有調整過，呼叫頻率也沒有大的變化。所以也可能是這個版本的bug。

週一上班後，應用反映最近幾天都出現了類似問題，所以和發生的週期沒有必然關係。

週二按照Leader的建議將函式、過程、觸發器pin到shared pool，希望減少過載和解析，觀察效果。週二17點左右再次出現，決定週三早上刪除直方圖觀察效果。

begin

DBMS_SHARED_POOL.KEEP ('owner.f_**','P');

end;

 

begin

DBMS_SHARED_POOL.KEEP ('owner.tr_**','R');

end;

 

週三早上刪除直方圖，週四中午12:58:25開始到00:01:35再次出現，決定週五凌晨修改session_cached_cursor重起資料庫觀察。

begin

dbms_stats.gather_table_stats(ownname=> '***', tabname=> '****', estimate_percent=>10 , partname=> NULL,cascade => true,method_opt => 'FOR ALL COLUMNS SIZE 1');

end;

 

同時週三在測試環境修改隱含引數_kks_use_mutex_pin關閉cursor MUTEX進行測試，準備不得以的情況下通過修改隱含引數恢復使用原有的library cache機制。

 

週四下午我們詳細的分析了v$active_session_history在出現問題時的情況，可以看到最初只有4個session在等待cursor: pin S wait on X，然後等待的session不斷的增加，並且已經等待的session一直都是在等待中，直到某個時間點，所有session的等待都結束了，系統恢復了正常執行。我一直很費解的是為啥要以獨佔的方式獲得鎖，這些都是很頻繁執行的sql，不需要反覆解析的，而且業務並不複雜，都是繫結變數的，總共就那麼幾個屈指可數的sql，sharedpool也足夠大了……總之是沒想明白。

在檢查v$active_session_history的時候，偶然發現在最初出現cursor: pin S wait on X等待的時候，伴隨兩個其他的等待事件，分別是buffer exterminate和library cache load lock，library cache load lock等待事件伴隨阻塞的期間一直存在，但是隻有一個session在等待，總體的等待時間很短。buffer exterminate等待事件則只在阻塞得最開始出現，馬上就消失了。所以這兩個等待事件在做效能分析報告的時候沒有表現出來。分析這兩個等待事件，buffer exterminate應該和sga的自動調整有關係，library cache load lock和sharedpool有關係，metalink上關於library cache load lock等待事件的建議是：

How to reduce the Library cache load lock?

==============================

If an object is not in memory, then a library cache lock cannot be acquired on it.

So the object has to be loaded into the memory to to acquire the lock.

Then the session tries to find the load lock for the database object so that it can load the object.

In order to prevent multiple processes to request the load of the same object simultaneously, the other requesting sessions have to wait for the library cache load lock as the lock is busy with loading the object into the memory.

 

The waits on the library cache load lock is due to the objects not available in the memory.

The inavailability of the library cache object in the library cache is due to the undersized shared pool causing reloads often, too many hard parse because of unshared sqls.

 

To avoid this, the general recommendation would be

1. To increase the shared pool ( to avoid the reloads often)

2. To increase the session cached cursors (to avoid the cursors flushing out of shared pool)

3. To set cursor_sharing to force (to reduce hard parsing)

由於sharedpool的大小是sga自動分配的，所以，我們系統修改session cached cursors觀察效果，這個引數我們原來使用的是預設值20，需要重起生效。

 

同時，檢查v$sga_resize_ops檢視，發現在出現阻塞期間有sga的動態調整，調整的時間和阻塞得時間基本吻合。而且這個檢視中記錄了大量的sga變化，一會兒sharedpool減少一點兒，給了db buffer，一會兒又改回去了，我們覺得這些自動調整地必要性並不是很高，且懷疑等待事件的產生和sga的自動調整有關係，所以決定重起時關閉sga的自動調整，固定各個池的大小。

       8月1日週五凌晨6點10分左右應用停服務，開始shutdown，shutdown時，資料庫報ora-600：

ORA-00600: internal error code, arguments: [LibraryCacheNotEmptyOnClose], [], [], [], [], [], [], []

當時因判斷和librarycache有關，應該不會影響啟動，所以沒有繼續跟蹤問題。

後來到公司後確認是oracle的bug：Bug 4483084 - OERI[LibraryCacheNotEmptyOnClose] on shutdown。

 

從重起到現在，沒有再出現cursor: pin S wait on X的等待事件，有可能是關閉sga自動調整導致的，也有可能跟資料庫重起有關，需要繼續觀察。

 

總結：

1、  v$active_session_history用來研究過去某個時間點的資料庫的狀況非常好用。

2、  SGA的自動調整的演算法不知道怎樣的，為什麼會調整地那麼頻繁，對於我們這種訪問比較固定且業務相對簡單的資料庫，也許不需要讓他自動調整更好些。

3、  如果可以，我還是傾向於使用9i的穩定版本，大部分的問題都有人遇到過了，都會有比較穩妥的解決方案。新版本雖然可以使用新特性，但是總給人不太穩妥的感覺。

 

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