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

資料和雲發表於2022-12-05

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

本文節選自《雲和恩墨技術通訊》(12月刊)
下載連結:

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

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的整體執行情況看:


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

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

檢視故障期間資料庫活動會話情況:

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


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

從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。

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

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。

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

從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等待。

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

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

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

導致SQL不共享的原因很多,一部分是由於SQL中繫結變數長度不一致導致。

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

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

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

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

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

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

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

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

此類等待事件往往都是發生在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連結串列上找出可共享的遊標。

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

檢視library cache中namespace的命中:

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

從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個是標記為過期的,檢視遊標不能被共享的原因:

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

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

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

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

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

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

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

綜合以上分析,造成大量遊標過期的原因有以下兩個
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

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

從上面截圖的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操作,並持續監控資料庫效能。

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

相關文章