前兩天與一個客戶交流的時候，客戶提出了一些對mysql隔離級别以及鎖的疑問，然後問到了出現鎖等待現象的排查思路。和客戶進行了簡單交流之後，翻了翻之前的一個診斷案例，當時折騰了兩三天，現在看看還是有些借鑒價值的。
<b>資料庫執行個體：</b>主庫xxxx:3306
<b>問題詳情：</b>客戶反映，涉及到user_site表相關的程式回調操作很慢，部分操作會逾時報錯；
下單操作很慢甚至直接報錯失敗
<b>程式端報錯資訊如下：</b>
general error: 1205 lock wait timeout exceeded; try restarting transaction"
這是個典型的鎖等待逾時退出的報錯，原因可能是某些事務未及時送出導緻鎖資源不被釋放導緻
思路：通過rds控制台檢視最近一段時間的慢sql，看是否出現user_site表相關的dml或者select鎖定讀操作。
檢視慢sql方式見下圖
很可惜，并沒有找到相關的慢sql，那麼就代表sql執行都很快，事務的處理上出現了問題，是以，我們更相信是某些程式沒有及時送出事務導緻的了。
不過，還是有些收獲的，我們發現一些潛在的問題，就是top前幾的慢sql。都是非鎖定select，是以和本次現象無關，但是這幾個查詢操作最長需要近百秒，十分消耗cpu以及記憶體資源，需要優化。
思路：通過一個腳本，定期采集出現阻塞的事務資訊，隻要再次進行相關操作，阻塞事件的參與事務資訊便被計入日志，可對其進行詳細分析。
采集腳本如下：
#!/bin/bash
sql="select r.trx_id waiting_trx_id,r.trx_mysql_thread_id waiting_thread,r.trx_query waiting_query,b.trx_id blocking_trx_id,b.trx_mysql_thread_id blocking_thread,b.trx_query blocking_query from information_schema.innodb_lock_waits w inner join information_schema.innodb_trx b on b.trx_id=w.blocking_trx_id inner join information_schema.innodb_trx r on r.trx_id=w.requesting_trx_id\g"
while :
do
echo "================================="
echo "采集時間："`date +%y-%m-%d_%h:%m:%s`
mysql -hxxxx -uxxxx -pxxxxxxxx -e "$sql"
echo ""
sleep 5
done
大約半小時後，日志中抓取到相關的資訊
通過分析日志，我們發現每隔一段時間會出現較為嚴重的連環鎖等待現象，主要是以下兩種情況
*************************** 1. row ***************************
waiting_trx_id: 8822773749
waiting_thread: 7297307
waiting_query: select funding from user_site where user_id = 38440594 and site_id = 3 for update
blocking_trx_id: 8822773748
blocking_thread: 7297310
blocking_query: select funding from user_site where user_id = 4 and site_id = 3 for update
*************************** 2. row ***************************
waiting_trx_id: 8822773748
waiting_thread: 7297310
waiting_query: select funding from user_site where user_id = 4 and site_id = 3 for update
blocking_trx_id: 8822602949
blocking_thread: 7120018
blocking_query: null
waiting_trx_id: 8814966658
waiting_thread: 15064606
waiting_query: update user_site set id='85989170', user_id='71457291', site_id='3', password='a14f
2c3bae708de1d439c1d796ab319b', funding='0.64', subscribe_weixin='0', subscribe_alipay='0', rank='0',
logintype='9', publishprojectnumber='0', supportnumber='4', follownumber='3', active='1', created='
2016-08-11 15:41:46', updated='2016-09-26 18:19:19', conf=null, identity='31' where id = 85989170
blocking_trx_id: 8814920762
blocking_thread: 15012709
解釋下上面的日志輸出：
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。送出事務之前，程式極有可能經過一個緩慢的處理過程，至于處理什麼，需要下一步做進一步的驗證。
接下來，對上面的推論做驗證
思路：想要找到是哪塊代碼的問題，盲目的找無疑是大海撈針，所幸的是，rds提供sql審計功能，隻要找到事務送出之前的sql操作，這個問題的定位就應該清晰明了了。
通過前面排查的線程id，搜尋相關的sql審計記錄。sql審計可以通過下圖方式檢視。
點選資料庫安全→sql審計。輸入篩選條件：database name，程式通路資料庫的使用者名，關鍵字輸入線程id，并選擇有效的時間範圍。
這次，終于有些收獲了，并且應該可以對本次現象做出合理的解釋了。以下是可疑的資料庫操作
我們發現，事務開啟後，立即進行了幾個sql操作，而這幾個sql都沒有被計入慢日志，是以sql執行很快(2s以内)，從前面的日志輸出我們也能看出，sql執行是瞬間完成的，因為我們根本抓取不到事務的sql語句。
而事務的送出操作卻發生在十幾分鐘之後，那麼現在的疑問就是解決問題的關鍵了。長達十幾分鐘的事務，而sql執行總共不到2s，那麼其餘的時間程式在幹什麼？
有了針對性的目的後，該客戶開發同學馬上定位到程式并找到了問題所在，在送出之前，程式會去進行插入隊列和删除緩存的操作，而這些操作，占用的都是事務的持有鎖且非活動時間。
屆此，該問題的分析過程全部結束，出現問題的原因就在于事務内部的非資料庫操作
事務内部進行的不隻是資料庫操作，程式進行的插入隊列以及删除緩存操作，讓一個2s之内完成的事務，延長至十幾分鐘；也就意味着，這十幾分鐘内，凡是請求事務内部鎖資源的sql操作，必須進入鎖等待狀态
1.事務内部隻進行sql操作，程式的處理一律放在事務送出之後或開始之前
2.如果存在邏輯問題不可修改，可為相關處理過程設計處理隊列，抛出指令即可，而不用等待這個過程處理完畢再送出事務