1.事故描述

本月 8 日上午十點多，我們的基礎應用發生生產事故。具體表象為系統出現假死無響應。
檢視事發時間段的基礎應用 error 日誌，沒發現明顯異常。檢視基礎應用業務日誌，銀行結果處理的部分普遍很慢，大都在十分鐘以上。

2.AWR 報告

向 DBA 要了一下那個時間段的 AWR 報告，發現以下三個地方有些異常：

2.1.CPU 利用率過高

如上圖所示，CPU利用率：1883.25分鐘DB時間/(16核心*119.45分鐘取樣時間段時間) = 98.54%，CPU 利用率過高。

2.2.行鎖等待嚴重

如上圖"Top 5 Timed Events"所示，行鎖等待佔用了 80% 的 CPU 時間，基本可以確定它就是造成本次生產事故的直接元凶。
所以我們直接跳到"Wait Events"排行榜：

這說明了什麼？在本次 AWR 報告的 09:00:45 - 11:00:12 大約 119.45 分鐘的時間裡，行鎖等待的時間為 99974 秒，合 1666.23 分鐘！
2.3.悲觀鎖慢查詢嚴重
那麼是什麼操作造成行鎖等待如此之嚴重呢？如此嚴重的行鎖等待，慢查詢統計列表裡應該很突出地指示出來，我們直接跳到"SQL ordered by Elapsed Time"慢查詢排行榜：

果不其然，兩個小時的時間內，id 為 3x0hq0nmj6a93 的那條 sql 查詢耗時 93158 秒(合 1552.63 分鐘)，平均每條執行時間為 306.44 秒(合 5.11 分鐘)，佔用了 80% 以上的的 CPU。
讓我們來看看這條 sql 的真面目吧：

select ORD_BILLNO, ORD_PRDCODE, ORD_CRCODE, ORD_MERBILLNO, ORD_PRETIME, 
ORD_DOTIME, ORD_MERTIME, ORD_MERCODEFROM, ORD_TYPEFROM, ORD_MERCODETO, 
ORD_TYPETO, ORD_ACCCODEFROM, ORD_ACCCODETO, ORD_AMT, ORD_STATUS, 
ORD_ATTACH, ORD_UPDATETIME, ORD_PRODUCT, ORD_REFUNDED, ORD_REFUSE, 
ORD_PREIP, ORD_ENDIP, ORD_BILLEXPTIME, ORD_DIRECTLY, ORD_SYSCODE, 
ORD_BRCCODE, ORD_SRCCODE, ORD_PAYEDAMT, TRD_CODE, RESV1, RESV2, 
RESV3, ORD_PRDCODE_OLD, TRD_CODE_OLD, ORD_USERACCTYPE from 
T_PSFP_ORDER_TMP where ORD_BILLNO = :1 for update
 

這是一條 select for update 資料庫悲觀鎖查詢語句，因為指定訂單號，所以會鎖定 T_PSFP_ORDER_TMP 表的某一條語句，印證了 2.2 中的結論。

3.程式碼分析

呼叫上述 sql 的程式碼：

Order tempOrder = orderTempDao.selectOrderByPrimaryKeyForUpdate(verifyResult.getBillNo());

該業務程式碼先拿到該臨時交易的鎖，然後繼續處理後續相當繁瑣業務邏輯，中間還有大量的其它資料庫操作，因為是宣告式事務處理，所以在整個業務邏輯執行結束之後才會 commit，這段時間內如果還有其它 session 想拿這個行鎖，就必須等到這一系列業務邏輯執行完畢。
正常情況下，這個邏輯是沒問題的，但是在高併發的時候，這些業務邏輯受到 CPU 及網路等資源的限制可能會被拖慢，業務邏輯處理慢倒沒什麼，可怕的是資料庫被拖慢，反過來又影響這些業務邏輯，形成一個滾雪球的效應，直至系統故障。

4.解決方案

技術中心不允許使用 select for update 悲觀鎖，尤其是在大量業務邏輯的情況下，至於原有業務邏輯可以使用其他處理方案進行替代。如必需使用 select for update，須與架構部討論後才可使用。

最後，關於Oracle AWR 報告的生成和分析請參考部落格《Oracle AWR 報告的生成和分析》。