一、背景
#### 20191219 10:10:10,234 | com.alibaba.druid.filter.logging.Log4jFilter.statementLogError(Log4jFilter.java:152) | ERROR | {conn-10593, pstmt-38675} execute error. update operation_service set offlinemark = ? , resourcestatus = ? where RowGuid = ? com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Lock wait timeout exceeded; try restarting transaction
-
行鎖等待超時
當 SQL 因為等待行鎖而超時，那么就為行鎖等待超時，常在多並發事務場景下出現。
-
元數據鎖等待超時
當 SQL 因為等待元數據鎖而超時，那么就為元數據鎖等待超時，常在 DDL 操作期間出現。
本文僅介紹如何有效解決行鎖等待超時，因為大多數項目都是此類錯誤，元數據鎖等待超時則不涉及講解。
二、行鎖的等待
在介紹如何解決行鎖等待問題前，先簡單介紹下這類問題產生的原因。
產生原因簡述：當多個事務同時去操作（增刪改）某一行數據的時候，MySQL 為了維護 ACID 特性，就會用鎖的形式來防止多個事務同時操作某一行數據，避免數據不一致。只有分配到行鎖的事務才有權力操作該數據行，直到該事務結束，才釋放行鎖，而其他沒有分配到行鎖的事務就會產生行鎖等待。如果等待時間超過了配置值（也就是 innodb_lock_wait_timeout 參數的值，個人習慣配置成 5s，MySQL 官方默認為 50s），則會拋出行鎖等待超時錯誤。
如上圖所示，事務 A 與事務 B 同時會去 Insert 一條主鍵值為 1 的數據，由於事務 A 首先獲取了主鍵值為 1 的行鎖，導致事務 B 因無法獲取行鎖而產生等待，等到事務 A 提交后，事務 B 才獲取該行鎖，完成提交。
這里強調的是行鎖的概念，雖然事務 B 重復插入了主鍵，但是在獲取行鎖之前，事務一直是處於行鎖等待的狀態，只有獲取行鎖后，才會報主鍵沖突的錯誤。
當然這種 Inster 行鎖沖突的問題比較少見，只有在大量並發插入場景下才會出現，項目上真正常見的是 update&delete 之間行鎖等待，這里只是用於示例，原理都是相同的。
三、產生的原因
根據我之前接觸到的此類問題，大致可以分為以下幾種原因：
update A set ... where ...in (select B) 這類級聯更新，不僅會占用 A 表上的行鎖，也會占用 B 表上的行鎖，當 SQL 執行較久時，很容易引起 B 表上的行鎖等待。
綜上可以看出，如果事務長時間未提交，且事務中包含了 DML 操作，那么就有可能產生行鎖等待，引起報錯。
四、定位難點
當 web 日志中出現行鎖超時錯誤后，很多開發都會找我來排查問題，這里說下問題定位的難點！
1. MySQL 本身不會主動記錄行鎖等待的相關信息，所以無法有效的進行事后分析。
2. 鎖爭用原因有多種，很難在事后判斷到底是哪一類問題場景，尤其是事后無法復現問題的時候。
3. 找到問題 SQL 后，開發無法有效從代碼中挖掘出完整的事務，這也和公司框架-產品-項目的架構有關，需要靠 DBA 事后采集完整的事務 SQL 才可以進行分析。
五、常用方法
先介紹下個人通常是如何解決此類問題的， 這里問題解決的前提是問題可以復現，只要不是突然出現一次，之后再也不出現，一般都是可以找到問題源頭的。
這里問題復現分為兩種情景：
下面先寫下統一的模擬場景，用於復現行鎖超時問題，便於大家理解：
--表結構 CREATE TABLE `emp` ( `id` int(11) NOT NULL, KEY `idx_id` (`id`) ) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 從1~100w插入100w行記錄。 --測試過程： 事務1： start transaction; delete from emp where id = 1; select * from emp where id in (select id from emp); -->模擬慢查詢，執行時間很久，事務因此一直不提交，行鎖也不釋放. commit; 事務2： start transaction; delete from emp where id < 10; --> 處於等待id=1的行鎖狀態，當達到行鎖超時時間（這里我配置了超時時間為 5s）后，返回行鎖超時報錯 rollback;
5.1 手動復現場景
這個場景通常只需要通過 innodb 行鎖等待腳本就可以知道當前 MySQL 的 innodb 行鎖等待情況，例如我們一邊模擬上述報錯場景（模擬頁面操作），另一邊使用腳本查詢（需要在超時之前查詢，否則超時報錯后就看不到了）。/*innodb 行鎖等待腳本 5.7版*/ SELECT r.trx_mysql_thread_id waiting_thread,r.trx_query waiting_query, concat(timestampdiff(SECOND,r.trx_wait_started,CURRENT_TIMESTAMP()),'s') AS duration, b.trx_mysql_thread_id blocking_thread,t.processlist_command state,b.trx_query blocking_current_query,e.sql_text blocking_last_query FROM information_schema.innodb_lock_waits w JOIN information_schema.innodb_trx b ON b.trx_id = w.blocking_trx_id JOIN information_schema.innodb_trx r ON r.trx_id = w.requesting_trx_id JOIN performance_schema.threads t on t.processlist_id = b.trx_mysql_thread_id JOIN performance_schema.events_statements_current e USING(thread_id) /*8.0版本*/ SELECT r.trx_mysql_thread_id waiting_thread,r.trx_query waiting_query, concat(timestampdiff(SECOND,r.trx_wait_started,CURRENT_TIMESTAMP()),'s') AS duration, b.trx_mysql_thread_id blocking_thread,t.processlist_command state,b.trx_query blocking_current_query,e.sql_text blocking_last_query FROM performance_schema.data_lock_waits w JOIN information_schema.innodb_trx b ON b.trx_id = w.BLOCKING_ENGINE_TRANSACTION_ID JOIN information_schema.innodb_trx r ON r.trx_id = w.REQUESTING_ENGINE_TRANSACTION_ID JOIN performance_schema.threads t on t.processlist_id = b.trx_mysql_thread_id JOIN performance_schema.events_statements_current e USING(thread_id)
如上我們可以看到事務 2 的線程 id 為 76，已經被事務 1，也就是線程 id 為 75 的事務阻塞了 3s，並且可以看到事務 1 當前執行的 SQL 為一個 SELECT。這里也解釋了很多開發經常問我的，為什么 SELECT 也會阻塞其他會話？
如果遇到這種情況，那么處理其實非常簡單。需要優化這個 SELECT 就好了，實在優化不了，把這個查詢扔到事務外就可以了，甚至都不需要挖掘出整個事務。
上述這個問題模擬，其實就是對應第三節問題產生原因中的第二點（事務中包含性能較差的查詢 SQL），下面我們把第一點（程序中非數據庫交互操作導致事務掛起）也模擬下，對比下現象。
事務1： start transaction; delete from emp where id = 1; select * from emp where id in (select id from emp); 等待60s(什么都不要做) --> 模擬接口調用超時，事務夯住，隨后再執行commit。 commit;
再次用腳本查看，可以看到現象是有所不同的，不同點在於，阻塞事務處於 sleep 狀態，即事務當前並不在跑 SQL。從 DBA 的角度看，這類現象八成就可以斷定是代碼在事務中嵌入了其他的交互操作導致的事務掛起（另外也有可能是網絡問題導致的事務僵死），因為程序並不像人，它不會偷懶，不會出現事務執行到一半，休息一會再提交一說。
如果是這類現象的問題，因為本質並不是由於 SQL 慢導致的事務掛起，所以必須要到代碼里去找到對應的點，看下到底是在做什么交互操作卡住了。
這里就需要開發去排查代碼才可以找到源頭，但是唯一可用的信息就是該事務最后執行的一條 SQL，也就是上圖中最后一列，從我之前的經驗來看（絕大時候），開發很難單從這一條 SQL 就可以找到代碼里具體位置，尤其是當這條 SQL 是一條很常見的 SQL，就更為困難！
當面對這種情況，就需要 DBA 去挖掘出這個事務執行過的所有 SQL，然后再讓開發去排查代碼，這樣難度應該就小多了。這里就需要用到 MySQL 的 general_log，該日志用於記錄 MySQL 中所有運行過的 SQL。
--查看general_log是否開啟，及文件名 mysql> show variables like '%general_log%'; +------------------+--------------------------------------+ | Variable_name | Value | +------------------+--------------------------------------+ | general_log | OFF | | general_log_file | /data/mysql_data/192-168-188-155.log | +------------------+--------------------------------------+ --暫時開啟general_log mysql> set global general_log = 1; Query OK, 0 rows affected (0.00 sec) --暫時關閉general_log mysql> set global general_log = 0; Query OK, 0 rows affected (0.00 sec)
開啟 general_log 后，手動復現的時候通過 innodb 行鎖等待腳本查詢結果中的線程 ID，去 general_log 找到對應的事務分析即可，如下：
select * from emp where id in (select id from emp) 后到真正提交，過了 1min 左右，原因要么就是這條 SQL 查詢慢，要么就是代碼在執行其他交互操作。
PS：general_log 由於會記錄所有 SQL，所以對 MySQL 性能影響較大，且容易暴漲，所以只在問題排查時暫時開啟，問題排查后，請及時關閉！
5.2 隨機復現場景
相較於手動復現場景，這種場景因為具有隨機性，所以無法一邊模擬報錯，一邊通過腳本查詢到具體的阻塞情況，因此需要通過其他方式來監控 MySQL 的阻塞情況。
#!/bin/bash #賬號、密碼、監控日志 user="root" password="Gepoint" logfile="/root/innodb_lock_monitor.log" while true do num=`mysql -u${user} -p${password} -e "select count(*) from information_schema.innodb_lock_waits" |grep -v count` if [[ $num -gt 0 ]];then date >> /root/innodb_lock_monitor.log mysql -u${user} -p${password} -e "SELECT r.trx_mysql_thread_id waiting_thread,r.trx_query waiting_query, \ concat(timestampdiff(SECOND,r.trx_wait_started,CURRENT_TIMESTAMP()),'s') AS duration,\ b.trx_mysql_thread_id blocking_thread,t.processlist_command state,b.trx_query blocking_query,e.sql_text \ FROM information_schema.innodb_lock_waits w \ JOIN information_schema.innodb_trx b ON b.trx_id = w.blocking_trx_id \ JOIN information_schema.innodb_trx r ON r.trx_id = w.requesting_trx_id \ JOIN performance_schema.threads t on t.processlist_id = b.trx_mysql_thread_id \ JOIN performance_schema.events_statements_current e USING(thread_id) \G " >> ${logfile} fi sleep 5 done
--使用 nohup 命令后台運行監控腳本 [root@192-168-188-155 ~]# nohup sh innodb_lock_monitor.sh & [2] 31464 nohup: ignoring input and appending output to ‘nohup.out’ --查看 nohup.out 是否出現報錯 [root@192-168-188-155 ~]# tail -f nohup.out mysql: [Warning] Using a password on the command line interface can be insecure. mysql: [Warning] Using a password on the command line interface can be insecure. mysql: [Warning] Using a password on the command line interface can be insecure. --定時查看監控日志是否有輸出(沒有輸出的話，這個日志也不會生成哦！) [root@192-168-188-155 ~]# tail -f innodb_lock_monitor.log Wed Feb 5 11:30:11 CST 2020 *************************** 1. row *************************** waiting_thread: 112 waiting_query: delete from emp where id < 10 duration: 3s blocking_thread: 111 state: Sleep blocking_query: NULL sql_text: select * from emp where id in (select id from emp)
-
如果是事務卡在慢 SQL，那么就需要優化 SQL。
-
如果是事務掛起，那么就通過 general_log 分析事務，然后找到具體的代碼位置。
PS：問題排查完成后，請及時關閉后台監控進程，通過
kill+pid 的方式直接關閉即可！
六、Performance_Schema
之前的方法感覺不是很方便，因為 general_log 需要訪問服務器，且過濾分析也較難，需要一定的 MySQL 基礎及 Linux 基礎才適用，因此想尋找一種更為簡便的方法。
個人想法是利用 MySQL 5.5 開始提供的 performance_schema 性能引擎來進行分析，Performance_Schema 是 MySQL 提供的在系統底層監視 MySQL 服務器性能的一個特性，其提供了大量監控項，包括：鎖、IO、事務、內存使用等。
介紹下主要原理：
1. 主要用的表有 2 張 events_transactions_history_long 和 events_statements_history_long。2. transactions_history_long 會記錄歷史事務信息，events_statements_history_long 則記錄歷史 SQL。3. 從 transactions_history_long 中得到回滾事務的線程 ID，再根據時間范圍去篩選出可疑的事務，最后從 events_statements_history_long 得到事務對應的 SQL，從中排查哪個為源頭。優點：
1. 不需要通過 general_log 來獲取事務 SQL。2. 不需要監控腳本來獲取到行鎖等待情況。3. 只需要訪問 MySQL 就可以實現，而不需要訪問服務器。4. 性能開銷較小，且不會暴漲，因為是循環覆蓋寫入的。5. 可以知道每條 SQL 的運行時長。缺點：
1. history_long 相關表默認保留記錄有限，可能會把有用的數據刷掉，尤其是在 SQL 運行較多的系統。2. 如果要加大 history_long 相關表的最大保留行數，需要重啟 MySQL，無法在線修改參數。3. history_long 相關表記錄中的時間均為相對時間，也就是距離 MySQL 啟動的時長，看起來不是很方便。4. history_long 相關表不會主動記錄行鎖等待的信息，所以只能通過先根據時間范圍刷選出可疑的事務，再進一步分析，不如腳本監控定位的准。/*開啟performance_schema相關監控項，需要提前開啟performance_schema*/ UPDATE performance_schema.setup_instruments SET ENABLED = 'YES', TIMED = 'YES' where name = 'transaction'; UPDATE performance_schema.setup_consumers SET ENABLED = 'YES' where name like '%events_transactions%'; UPDATE performance_schema.setup_consumers SET ENABLED = 'YES' where name like '%events_statements%'; /*查看回滾事務SQL，確認是否是日志里報錯的事務*/ SELECT a.THREAD_ID ,b.EVENT_ID ,a.EVENT_NAME ,CONCAT (b.TIMER_WAIT / 1000000000000,'s') AS trx_druation ,CONCAT (a.TIMER_WAIT / 1000000000000,'s') sql_druation ,a.SQL_TEXT,b.STATE,a.MESSAGE_TEXT FROM performance_schema.events_statements_history_long a JOIN performance_schema.events_transactions_history_long b ON a.THREAD_ID = b.THREAD_ID AND (a.NESTING_EVENT_ID = b.EVENT_ID OR a.EVENT_ID = b.NESTING_EVENT_ID) WHERE b.autocommit = 'NO' AND a.SQL_TEXT IS NOT NULL AND b.STATE = 'ROLLED BACK' /*查看該時間段內可疑事務即超過5s的事務SQL，這里默認innodb_lock_wait_timeout為5s*/ SELECT a.THREAD_ID ,b.EVENT_ID ,a.EVENT_NAME ,CONCAT (b.TIMER_WAIT / 1000000000000,'s') AS trx_druation ,CONCAT (a.TIMER_WAIT / 1000000000000,'s') sql_druation ,a.SQL_TEXT,b.STATE,a.MESSAGE_TEXT,a.ROWS_AFFECTED,a.ROWS_EXAMINED,a.ROWS_SENT FROM performance_schema.events_statements_history_long a JOIN performance_schema.events_transactions_history_long b ON a.THREAD_ID = b.THREAD_ID AND (a.NESTING_EVENT_ID = b.EVENT_ID OR a.EVENT_ID = b.NESTING_EVENT_ID) WHERE b.autocommit = 'NO' AND SQL_TEXT IS NOT NULL AND b.STATE = 'COMMITTED' AND b.TIMER_WAIT / 1000000000000 > 5 AND b.TIMER_START < (SELECT TIMER_START FROM performance_schema.events_transactions_history_long WHERE THREAD_ID = 70402 /*上述SQL查詢結果中的線程ID*/ AND EVENT_ID = 518) /*上述SQL查詢結果中的事件ID*/ AND b.TIMER_END > ( SELECT TIMER_END FROM performance_schema.events_transactions_history_long WHERE THREAD_ID = 70402 /*上述SQL查詢結果中的線程ID*/ AND EVENT_ID = 518) /*上述SQL查詢結果中的事件ID*/ ORDER BY a.THREAD_ID
6.2 測試模擬
這里由於是測試環境模擬，所以結果非常了然，項目上實際輸出結果可能有很多，需要一一分析事務是否有問題！
七、總結
實際測試后，發現通過 performance_schema 來排查行鎖等待超時問題限制其實也比較多，而且最后的分析也是一門技術活，並不如一開始想象的那么簡單，有點事與願違了。