技本功丨一個鎖等待現(xiàn)象的診斷案例

1、慢SQL分析

思路：通過rds控制臺查看最近一段時間的慢SQL，看是否出現(xiàn)user_site表相關的DML或者select鎖定讀操作。 

查看慢SQL方式見下圖

很可惜，并沒有找到相關的慢SQL，那么就代表SQL執(zhí)行都很快，事務的處理上出現(xiàn)了問題，因此，我們更相信是某些程序沒有及時提交事務導致的了。

不過，還是有些收獲的，我們發(fā)現(xiàn)一些潛在的問題，就是top前幾的慢SQL。都是非鎖定select，因此和本次現(xiàn)象無關，但是這幾個查詢操作最長需要近百秒，十分消耗CPU以及內存資源，需要優(yōu)化。

2、事務阻塞分析

思路：通過一個腳本，定期采集出現(xiàn)阻塞的事務信息，只要再次進行相關操作，阻塞事件的參與事務信息便被計入日志，可對其進行詳細分析。 

采集腳本如下：

大約半小時后，日志中抓取到相關的信息

通過分析日志，我們發(fā)現(xiàn)每隔一段時間會出現(xiàn)較為嚴重的連環(huán)鎖等待現(xiàn)象，主要是以下兩種情況：

解釋下上面的日志輸出：

waiting_trx_id: 被阻塞的事務ID

waiting_thread:被阻塞的mysql線程ID

waiting_query:被阻塞的SQL語句

blocking_trx_id: 阻塞者的事務ID

blocking_thread: 阻塞者的mysql線程ID

blocking_query: 阻塞者的SQL語句

我們發(fā)現(xiàn)，阻塞者總是處于非活躍狀態(tài)，而后的相繼操作會進入一個等待隊列。之所以會發(fā)生阻塞，就是這個空事務持有著被阻塞事務所需要的鎖資源，也就是說，以鎖定的方式，訪問到了相同的記錄。

參考前面的慢SQL分析結果，進一步推論，事務內部的SQL執(zhí)行應該是較快的，那么程序可能處理完SQL之后沒有進行提交操作。

定位程序

與客戶開發(fā)同學后溝通后，對該場景進行重現(xiàn)。實時輸出日志，得到阻塞者的線程ID，通過information_schema.processlist視圖查詢出訪問mysql數(shù)據(jù)庫的程序。

客戶開發(fā)同學仔細排查代碼，很可惜也并沒有發(fā)現(xiàn)未提交事務的代碼。那么問題就可能出現(xiàn)在程序自身，是程序處理慢，而并非SQL。提交事務之前，程序極有可能經過一個緩慢的處理過程，至于處理什么，需要下一步做進一步的驗證。

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

3、SQL審計分析

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

通過前面排查的線程ID，搜索相關的SQL審計記錄。SQL審計可以通過下圖方式查看。 

點擊數(shù)據(jù)庫安全→SQL審計。輸入篩選條件：database name，程序訪問數(shù)據(jù)庫的用戶名，關鍵字輸入線程ID，并選擇有效的時間范圍。

這次，終于有些收獲了，并且應該可以對本次現(xiàn)象做出合理的解釋了。以下是可疑的數(shù)據(jù)庫操作 

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

而事務的提交操作卻發(fā)生在十幾分鐘之后，那么現(xiàn)在的疑問就是解決問題的關鍵了。長達十幾分鐘的事務，而SQL執(zhí)行總共不到2S，那么其余的時間程序在干什么？

有了針對性的目的后，該客戶開發(fā)同學馬上定位到程序并找到了問題所在，在提交之前，程序會去進行插入隊列和刪除緩存的操作，而這些操作，占用的都是事務的持有鎖且非活動時間。

屆此，該問題的分析過程全部結束，出現(xiàn)問題的原因就在于事務內部的非數(shù)據(jù)庫操作 。