重啟大法失效？詳述Oracle11g因JDBC bug引發異常Library Cache Lock等待處理事件

2019 年 12 月 30 日
筆記

墨墨導讀：在Oracle 11g 版本中可能出現由於JDBC bug導致sql綁定變數無法共享，過期游標過多的情況，此時如果發生大量並發業務，很有可能造成異常library cache lock等待事件，造成資料庫突發性能問題。在此，我們分享一次由jdbc bug和綁定變數長度問題共同「作案」引發資料庫性能故障的案例。

本文節選自《雲和恩墨技術通訊》（12月刊）下載鏈接：https://www.modb.pro/doc/1593（點擊閱讀原文或者掃描下方二維碼即可下載）

library cache lock等待事件是Oracle資料庫較為常見的等待事件之一，在之前的幾次月刊中，我們也提到過產生library cache lock等待出現的原因有很多，如登錄密碼錯誤嘗試過多、熱表收集統計資訊和SQL解析失敗等。

在Oracle 11g 版本中可能出現由於JDBC bug導致sql綁定變數無法共享，過期游標過多的情況，此時如果發生大量並發業務，很有可能造成異常library cache lock等待事件，造成資料庫突發性能問題。在此，我們分享一次由jdbc bug和綁定變數長度問題共同「作案」引發資料庫性能故障的案例，供各位參考。

問題描述

2019年10月11號晚22:00分左右，運維人員對生產系統資料庫進行清理歷史分區操作，執行近100個分區刪除操作後（22:05左右）發現該資料庫壓力飆升，維護人員緊急停止歷史分區清理操作，發現大量業務數據插入（INSERT）緩慢。

查看故障期間資料庫發現大量library cache lock等待，資料庫活動會話飆升至1000以上，資料庫響應非常緩慢，業務受到嚴重影響。

問題分析

從故障期間ASH的整體運行情況看：

從22:00開始，資料庫的活動會話飆升，每秒活動會話飆升至1000以上。故障時間段內的TOP EVENT主要表現在library cache lock和library cache: mutex X等待上。

查看故障期間資料庫活動會話情況：

從10:00:08的ash資訊來看，多個library cache lock被4276會話阻塞，4276會話被4374會話「cursor : mutex S」阻塞，同時4374會話被8168「library cache lock」阻塞。從ash分析來看，大量的library cache lock會話的p3值都是5373954和5373955。5373954指的是mode=2，5373955的mode=3，只是持有的方式不同mode=3就是exclusive獨佔鎖。

而4276會話library cache lock的p3值是5373955，對應的namespace HEX:52 —>DEC:82，mode=3。

SQL AREA BUILD說明library cache lock是在SQL解析上或SQL AREA上的問題。發生等待是會話都是在執行g14zxrn7wyaxh INSERT SQL語句：

/** PayOrderMapper.insert */  INSERT INTO TxxxxxxT T    (T.ID,……T.SxxxO)  VALUES    (SEQ_xxx.nextval,     :1,:2,:3,:4,:5,:6,:7,:8,:9,:10,:11,:12,:13,:14,:15,:16,:17,:18,:19,:20,:21,:22,:23,:24,:25,:26,:27,:28,:29,:30,:31,:32,:33,:34,:35,:36,:37,:38,:39,:40,:41,:42,:43,:44,:45,:46,SYSDATE,:47,SYSDATE,:48,:49,:50,:51)

該SQL中有51個綁定變數，多個綁定變數可能會導致bind variable graduation問題出現，繼而導致cursor無法被shared。

從ASH和DBA_HIST_SQLSTAT中可以看出21:45分之後SQL頻繁load到cursor cache中，其中invalidations有120次，這是從DASH中取的數據，實際數值比取樣還要大，另外SQL的LOADED_VERSION從原來的2431個在短時間內增長到5411個，實際的version count由於11.2.0.3的隱含參數_cursor_obsolete_threshold的關係，version count超過100會重新開始。

這個時候就懷疑是由於SQL的子游標過多引起SQL解析時遍歷library cache object handle鏈表需要很長時間，造成了library cache: mutex x等待。

在資料庫中可以看出大量loaded_version超過1000的SQL語句，並且其中有大量游標是過期的。其中SQL_ID：g14zxrn7wyaxh就是此次library cache lock等待最為嚴重的SQL。

導致SQL不共享的原因很多，一部分是由於SQL中綁定變數長度不一致導致。

採集故障期間的AWR，發現當時DB TIME接近2w，平均活動會話達到1200+。

排在前五的等待事件都屬於並發類的等待事件，其中cursor：mutex S等待次數最多。

從ASH中分析library cache lock可以得出，多個會話等待library cache lock主要發生在SQL AREA BUILD的mutex持有爭用上。Library cache: mutex X 是10.2.0.2之後library cache latch衍生出來等待。

以下是部分等待事件的含義：

此類等待事件往往都是發生在SQL解析前遍歷library cache object handle鏈表找到shared cursor。

查看AWR中的Mutex Sleep資訊發現：Mutex主要有三個函數的sleep是非常高的，kgllkal3 82、kkshGetNextChild[KKSHBKLOC1]、kglUpgradeLock 119。

函數-kgllkal3 82:kglkal的意思就是kernel generic library cache management library cache lock allocate 82的意思就是SQL AREA BUILD的意思。

函數-kkshGetNextChild [KKSHBKLOC1]:kksh的意思是kernel compile shared objects (cursor) cursor hash table，就是shared cursor的hash鏈表。持有mutex從library cache 的handle的hash鏈表上找出可共享的游標。

查看library cache中namespace的命中：

從AWR中可以看出SQL AREA BUILD被請求次數是最多的，這跟ASH中大量library cache lock是吻合的，SQL AREA中cursro reloads次數也達到10740次。Invali_dations達到1170次，說明有很多cursor失效了。

造成library cache lock等一系列嚴重等待事件的原因是大量的過期游標導致sql解析前花了大量時間去遍歷library cache object handle，問題SQL的5415個cursor中有5367個是標記為過期的，查看游標不能被共享的原因：

造成游標不能被共享的原因中有5257個游標的原因是Bind Mismatch(22)，也就是綁定變數的字元長度發生變化，從32位升級到128位。

其中Bind mismatch(14)的也有3294個，這個主要是綁定變數TIMESTAMP類型傳值到DATE類型導致的問題。Bind mismatch(14)多發生在第6個綁定變數上，對應表中第7個欄位，該欄位正好的DATE類型。

綜合以上分析,造成大量游標過期的原因有以下兩個： 1、綁定變數長度導致游標無法共享 2、JDBC的bug導致日期類型通過TIMESTAMP傳值，繼而導致綁定變數無法共享

相關bug：

Bug 18617175 : JDBC THIN SENDS SCALE VALUE OF 0 OR 9 FOR BINDS CAUSING MANY CHILD CURSORS  Bug 12596686 : JDBC THIN APP SENDS SCALE VALUE OF 0 OR 9 FOR BINDS CAUSING MANY CHILD CURSORS  Patch 12596686: JDBC THIN APP SENDS SCALE VALUE OF 0 OR 9 FOR BINDS CAUSING MANY CHILD CURSORS

從上面截圖的MOS文檔來看，JDBC版本升級到11203或11204仍有發生此例綁定變數傳值問題。

為什麼重啟應用無法解決？

1、kill session：故障發生後資料庫端進行kill session操作，但是因為有連接池，所以連接池會嘗試重連資料庫，kill 後的重連在連接池上幾乎是並發的，因此負載也很高，所以kill session不行；

2、重啟應用：重啟應用前資料庫端的latch競爭一直都有，大量的活動會話並沒有釋放。如果這個時候重啟應用還是會有新的連接進來，這些新進的連接依然會進入到隊列中等待，繼而加劇爭用，因為重啟並不會中止資料庫上之前的連接，所以重啟應用也不行；

3、關閉應用並kill session：應該關閉應用，然後資料庫端kill session，再啟動應用。

問題解決

建議一：後期進行歷史分區清理的操作（DDL操作同類）時，需提前查詢表上SQL的游標是否超過200，如超過這個閾值，應主動使用DBMS_SHARED_POOL.PURGE的方式將過期的游標清理出記憶體，儘可能的減少遍歷游標HASH鏈表時間較長的現象；

查詢並清理過期游標的SQL：

select q'[exec sys.dbms_shared_pool.purge(']' || address || ',' ||          hash_value || q'[','C');]' as flush_sql    from v$sql t   where t.sql_id = '&sqlid'     and t.is_obsolete = 'Y'     group by address,hash_value;

建議二：從應用層面，建議將前述同一個SQLID(g14zxrn7wyaxh)的SQL文本，通過在原SQL文本中，加入不同的注釋，從而將其變為若干個不同SQLID，但功能相同的SQL。其目的也是業務峰期時，將訪問分散到不同的父游標上。

其他建議： 1、將單個SQL游標總數加入到監控告警中，前提是v$sql_shared_cursor中的游標總量在閾值內，目前根據測試和經驗總結建議閾值設置為200；

2、資料庫分區維護操作屬於DDL操作，影響較大，應選擇業務最低峰期進行操作；

3、資料庫上執行DDL操作時，應實時監控資料庫的活動會話等待事件，如果出現mutex或latch等待持續上升，應立即取消DDL操作，並持續監控資料庫性能。