1. 程式人生 > >技本功丨一個鎖等待現象的診斷案例

技本功丨一個鎖等待現象的診斷案例

微信圖片_20181206142359.png

作者:蘇坡 袋鼠云云服務部-DBA團隊 資料庫工程師


前兩日與一個客戶交流,客戶提出了一些對mysql隔離級別以及鎖的疑問,然後問到了出現鎖等待現象的排查思路。這不禁讓我回想起,long long ago,做過的一個診斷案例。當年我還不是一枚老司機,折騰了兩三天才完全搞定,現在回想還頗有些借鑑價值,故,分享之~


微信圖片_201812061423591.png


1 問題描述

資料庫例項:主庫XXXX:3306 

問題詳情:客戶反映,涉及到user_site表相關的程式回撥操作很慢,部分操作會超時報錯;

下單操作很慢甚至直接報錯失敗

程式端報錯資訊如下:

General error: 1205 Lock wait timeout exceeded; try restarting transaction"


2 分析

這是個典型的鎖等待超時退出的報錯,原因可能是某些事務未及時提交導致鎖資源不被釋放導致。

1、慢SQL分析

思路:通過rds控制檯檢視最近一段時間的慢SQL,看是否出現user_site表相關的DML或者select鎖定讀操作。 

檢視慢SQL方式見下圖

微信圖片_201812061423592.png

很可惜,並沒有找到相關的慢SQL,那麼就代表SQL執行都很快,事務的處理上出現了問題,因此,我們更相信是某些程式沒有及時提交事務導致的了。

不過,還是有些收穫的,我們發現一些潛在的問題,就是top前幾的慢SQL。都是非鎖定select,因此和本次現象無關,但是這幾個查詢操作最長需要近百秒,十分消耗CPU以及記憶體資源,需要優化。

2、事務阻塞分析

思路:通過一個指令碼,定期採集出現阻塞的事務資訊,只要再次進行相關操作,阻塞事件的參與事務資訊便被計入日誌,可對其進行詳細分析。 

採集指令碼如下:

微信圖片_201812061423593.png


大約半小時後,日誌中抓取到相關的資訊

通過分析日誌,我們發現每隔一段時間會出現較為嚴重的連環鎖等待現象,主要是以下兩種情況:

微信圖片_201812061423594.png

微信圖片_201812061423595.png


解釋下上面的日誌輸出:

waiting_trx_id: 被阻塞的事務ID

waiting_thread:被阻塞的mysql執行緒ID

waiting_query:被阻塞的SQL語句

blocking_trx_id: 阻塞者的事務ID

blocking_thread: 阻塞者的mysql執行緒ID

blocking_query: 阻塞者的SQL語句

 

我們發現,阻塞者總是處於非活躍狀態,而後的相繼操作會進入一個等待佇列。之所以會發生阻塞,就是這個空事務持有著被阻塞事務所需要的鎖資源,也就是說,以鎖定的方式,訪問到了相同的記錄。

參考前面的慢SQL分析結果,進一步推論,事務內部的SQL執行應該是較快的,那麼程式可能處理完SQL之後沒有進行提交操作。

定位程式

與客戶開發同學後溝通後,對該場景進行重現。實時輸出日誌,得到阻塞者的執行緒ID,通過information_schema.processlist檢視查詢出訪問mysql資料庫的程式。

客戶開發同學仔細排查程式碼,很可惜也並沒有發現未提交事務的程式碼。那麼問題就可能出現在程式自身,是程式處理慢,而並非SQL。提交事務之前,程式極有可能經過一個緩慢的處理過程,至於處理什麼,需要下一步做進一步的驗證。

接下來,對上面的推論做驗證~

3、SQL審計分析

思路:想要找到是哪塊程式碼的問題,盲目的找無疑是大海撈針,所幸的是,RDS提供SQL審計功能,只要找到事務提交之前的SQL操作,這個問題的定位就應該清晰明瞭了。

通過前面排查的執行緒ID,搜尋相關的SQL審計記錄。SQL審計可以通過下圖方式檢視。 

微信圖片_201812061423596.png

點選資料庫安全→SQL審計。輸入篩選條件:database name,程式訪問資料庫的使用者名稱,關鍵字輸入執行緒ID,並選擇有效的時間範圍。 

這次,終於有些收穫了,並且應該可以對本次現象做出合理的解釋了。以下是可疑的資料庫操作:


我們發現,事務開啟後,立即進行了幾個SQL操作,而這幾個SQL都沒有被計入慢日誌,因此SQL執行很快(2S以內),從前面的日誌輸出我們也能看出,SQL執行是瞬間完成的,因為我們根本抓取不到事務的SQL語句。

而事務的提交操作卻發生在十幾分鍾之後,那麼現在的疑問就是解決問題的關鍵了。長達十幾分鐘的事務,而SQL執行總共不到2S,那麼其餘的時間程式在幹什麼?

有了針對性的目的後,該客戶開發同學馬上定位到程式並找到了問題所在,在提交之前,程式會去進行插入佇列和刪除快取的操作,而這些操作,佔用的都是事務的持有鎖且非活動時間。

屆此,該問題的分析過程全部結束,出現問題的原因就在於事務內部的非資料庫操作 。

微信圖片_201812061423597.png

fe24ec1bf8dc4a29a9ddb14cb2386c9.png

3 處理方案

根因分析

事務內部進行的不只是資料庫操作,程式進行的插入佇列以及刪除快取操作,讓一個2S之內完成的事務,延長至十幾分鍾;也就意味著,這十幾分鍾內,凡是請求事務內部鎖資源的SQL操作,必須進入鎖等待狀態。

處理建議

1.事務內部只進行SQL操作,程式的處理一律放在事務提交之後或開始之前。

2.如果存在邏輯問題不可修改,可為相關處理過程設計處理佇列,丟擲指令即可,而不用等待這個過程處理完畢再提交事務。