1. 程式人生 > 其它 >記錄一次線上 Oracle 資料庫 ORA-00060: deadlock detected 故障案例

記錄一次線上 Oracle 資料庫 ORA-00060: deadlock detected 故障案例

技術標籤:ORA-0006000060死鎖資料庫死鎖Oracle死鎖

客戶報告在做 job 匯入的時候偶爾會碰到 ORA-00060 錯誤,客戶端日誌如下:

2020-11-23 12:22:15 (GMT+0100) [ERROR] : java.sql.SQLException: ORA-00060: deadlock detected while waiting for resource

因為碰不到客戶的生產環境,所以要了一下他們的服務端日誌。一般來講,ORA-00060 總是結對出現,然後我們根據這個錯誤丟擲的程式呼叫棧,可以分別找到對應的兩個執行緒,根據上下文及各自的 sql 語句不難得出資料庫死鎖的原因所在。
但本文案例有些特殊,屬於二般情況。拿到服務端日誌以後直奔 ORA-00060 的拋錯呼叫棧而去,卻發現只有一種執行緒棧,對應的 sql 語句也只有一種:

update jobother set jobother.allocatestatus='C'  where job_unid in (142000000000397637,140000000000397301,140000000000397302,140000000000397303,140000000000397304,140000000000397543,140000000000397548,140000000000397638,140000000000397639,140000000000397640,140000000000397641,140000000000397642,140000000000397643)

走到這裡,先頭腦風暴一下。

  • 上述 sql 在同一時間段內有五處日誌列印,難道是重複執行?
  • 對端死鎖 sql 是什麼,服務端日誌裡沒有發現 00060 下的其他 sql,難道上述 sql 的 session 拋 00060 後對端執行緒就能得以成功執行?
  • 抑或是上述 sql 由五個執行緒同時執行,它們同時執行了同樣的邏輯,但為何會有五個相同的業務邏輯在同時執行,是客戶端重複請求還是介面沒有做好冪等性設計?

帶著這些疑問去問客戶要了 trc 檔案,直奔 Deadlock graph:
Deadlock graph.png

可見這是一個 Transaction Deadlock 型死鎖。查詢 session 425 的當前 sql:

update jobother set jobother.allocatestatus=:1   where job_unid in (142000000000405269,140000000000405066,140000000000405237,140000000000405264,140000000000405272,140000000000405275,140000000000405277,140000000000405279
,140000000000405281,140000000000405283,140000000000405285,140000000000405287,140000000000405289,140000000000405291)

然後再找到 session 627 的當前執行 sql:

update jobother set jobother.allocatestatus=:1   where job_unid in (142000000000405269,140000000000405066,140000000000405237,140000000000405264,140000000000405272,140000000000405275,140000000000405277,140000000000405279,140000000000405281,140000000000405283,140000000000405285,140000000000405287,140000000000405289,140000000000405291)

對比之下,它們其實是一樣的,頭腦風暴 3 命中。這個線索很關鍵,這個分散式環境中 db 這一塊的情況已經清晰明瞭。目前要做的事情則是找到介面介入的源頭情況。帶著它回過頭去繼續去分析服務端日誌。兩路並進,按圖索驥:

  • 找到 00060 丟擲的執行緒棧,找到該處程式碼往前捋;
  • 在服務端日誌 00060 處丟擲,結合相關程式碼往前捋。

兩路互相結合參考分析,接著就發現確實有 5 個執行緒在執行同樣的邏輯。重複請求?抑或是多執行緒誤啟了 5 個執行緒執行同樣邏輯?帶著這些疑問繼續往前捋,最終發現是確實有 5 個檔案需要匯入,五個不同的任務執行緒分別同時執行匯入,在執行到上述 sql 時造成死鎖:

cargoMateFinishedQueue/ID:Defonds-Prod-App.hhh-37181-1606128682104-1:1:2189:1:1 cargoMateFinishedQueue/ID:Defonds-Prod-App.hhh-37181-1606128682104-1:1:2197:1:1 cargoMateFinishedQueue/ID:Defonds-Prod-App.hhh-37181-1606128682104-1:1:2200:1:1 cargoMateFinishedQueue/ID:Defonds-Prod-App.hhh-37181-1606128682104-1:1:2207:1:1 cargoMateFinishedQueue/ID:Defonds-Prod-App.hhh-37181-1606128682104-1:1:2213:1:1

經分析,這 5 個檔案是同樣的內容,導致問題的根本完全是上游伺服器誤生成了同樣不同名的五個匯入檔案,並非是下游 job 匯入伺服器的介面冪等性問題。