有效解決 MySQL 行鎖等待超時問題
一、背景
- #### 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
上述這個錯誤，接觸 MySQL 的同學(xué)或多或少應(yīng)該都遇到過，專業(yè)一點來說，這個報錯我們稱之為鎖等待超時。根據(jù)鎖的類型主要細(xì)分為：
- 行鎖等待超時
當(dāng) SQL 因為等待行鎖而超時，那么就為行鎖等待超時，常在多并發(fā)事務(wù)場景下出現(xiàn)。
- 元數(shù)據(jù)鎖等待超時
當(dāng) SQL 因為等待元數(shù)據(jù)鎖而超時，那么就為元數(shù)據(jù)鎖等待超時，常在 DDL 操作期間出現(xiàn)。
本文僅介紹如何有效解決行鎖等待超時，因為大多數(shù)項目都是此類錯誤，元數(shù)據(jù)鎖等待超時則不涉及講解。
二、行鎖的等待
在介紹如何解決行鎖等待問題前，先簡單介紹下這類問題產(chǎn)生的原因。產(chǎn)生原因簡述：當(dāng)多個事務(wù)同時去操作(增刪改)某一行數(shù)據(jù)的時候，MySQL 為了維護 ACID 特性，就會用鎖的形式來防止多個事務(wù)同時操作某一行數(shù)據(jù)，避免數(shù)據(jù)不一致。只有分配到行鎖的事務(wù)才有權(quán)力操作該數(shù)據(jù)行，直到該事務(wù)結(jié)束，才釋放行鎖，而其他沒有分配到行鎖的事務(wù)就會產(chǎn)生行鎖等待。如果等待時間超過了配置值(也就是 innodb_lock_wait_timeout 參數(shù)的值，個人習(xí)慣配置成 5s，MySQL 官方默認(rèn)為 50s)，則會拋出行鎖等待超時錯誤。
如上圖所示，事務(wù) A 與事務(wù) B 同時會去 Insert 一條主鍵值為 1 的數(shù)據(jù)，由于事務(wù) A 首先獲取了主鍵值為 1 的行鎖，導(dǎo)致事務(wù) B 因無法獲取行鎖而產(chǎn)生等待，等到事務(wù) A 提交后，事務(wù) B 才獲取該行鎖，完成提交。這里強調(diào)的是行鎖的概念，雖然事務(wù) B 重復(fù)插入了主鍵，但是在獲取行鎖之前，事務(wù)一直是處于行鎖等待的狀態(tài)，只有獲取行鎖后，才會報主鍵沖突的錯誤。當(dāng)然這種 Insert 行鎖沖突的問題比較少見，只有在大量并發(fā)插入場景下才會出現(xiàn)，項目上真正常見的是 update&delete 之間行鎖等待，這里只是用于示例，原理都是相同的。
三、產(chǎn)生的原因
根據(jù)我之前接觸到的此類問題，大致可以分為以下幾種原因：
1. 程序中非數(shù)據(jù)庫交互操作導(dǎo)致事務(wù)掛起
將接口調(diào)用或者文件操作等這一類非數(shù)據(jù)庫交互操作嵌入在 SQL 事務(wù)代碼之中，那么整個事務(wù)很有可能因此掛起(接口不通等待超時或是上傳下載大附件)。
2. 事務(wù)中包含性能較差的查詢SQL
事務(wù)中存在慢查詢，導(dǎo)致同一個事務(wù)中的其他 DML 無法及時釋放占用的行鎖，引起行鎖等待。
3. 單個事務(wù)中包含大量 SQL
通常是由于在事務(wù)代碼中加入 for 循環(huán)導(dǎo)致，雖然單個 SQL 運行很快，但是 SQL 數(shù)量一大，事務(wù)就會很慢。
4. 級聯(lián)更新 SQL 執(zhí)行時間較久
這類 SQL 容易讓人產(chǎn)生錯覺，例如：update A set ... where ...in (select B) 這類級聯(lián)更新，不僅會占用 A 表上的行鎖，也會占用 B 表上的行鎖，當(dāng) SQL 執(zhí)行較久時，很容易引起 B 表上的行鎖等待。
5. 磁盤問題導(dǎo)致的事務(wù)掛起
極少出現(xiàn)的情形，比如存儲突然離線，SQL 執(zhí)行會卡在內(nèi)核調(diào)用磁盤的步驟上，一直等待，事務(wù)無法提交。綜上可以看出，如果事務(wù)長時間未提交，且事務(wù)中包含了 DML 操作，那么就有可能產(chǎn)生行鎖等待，引起報錯。
四、定位難點當(dāng)
web 日志中出現(xiàn)行鎖超時錯誤后，很多開發(fā)都會找我來排查問題，這里說下問題定位的難點!
1. MySQL 本身不會主動記錄行鎖等待的相關(guān)信息，所以無法有效的進行事后分析。
2. 鎖爭用原因有多種，很難在事后判斷到底是哪一類問題場景，尤其是事后無法復(fù)現(xiàn)問題的時候。
3. 找到問題 SQL 后，開發(fā)無法有效從代碼中挖掘出完整的事務(wù)，這也和公司框架-產(chǎn)品-項目的架構(gòu)有關(guān)，需要靠 DBA 事后采集完整的事務(wù) SQL 才可以進行分析。
五、常用方法
先介紹下個人通常是如何解決此類問題的， 這里問題解決的前提是問題可以復(fù)現(xiàn)，只要不是突然出現(xiàn)一次，之后再也不出現(xiàn)，一般都是可以找到問題源頭的。
這里問題復(fù)現(xiàn)分為兩種情景：
1. 手動復(fù)現(xiàn)
只要按照一定的操作，就可以復(fù)現(xiàn)報錯，這種場景較簡單!
2. 隨機復(fù)現(xiàn)
不知道何時會突然報錯，無法手動復(fù)現(xiàn)，這種場景較難!
下面先寫下統(tǒng)一的模擬場景，用于復(fù)現(xiàn)行鎖超時問題，便于大家理解：
- --表結(jié)構(gòu)
- CREATE TABLE `emp` (
- `id` int(11) NOT NULL,
- KEY `idx_id` (`id`)
- ) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4
- 從1~100w插入100w行記錄。
- --測試過程：
- 事務(wù)1：
- start transaction;
- delete from emp where id = 1;
- select * from emp where id in (select id from emp); -->模擬慢查詢，執(zhí)行時間很久，事務(wù)因此一直不提交，行鎖也不釋放.
- commit;
- 事務(wù)2：
- start transaction;
- delete from emp where id < 10; --> 處于等待id=1的行鎖狀態(tài)，當(dāng)達到行鎖超時時間（這里我配置了超時時間為 5s）后，返回行鎖超時報錯
- rollback;
5.1 手動復(fù)現(xiàn)場景
這個場景通常只需要通過 innodb 行鎖等待腳本就可以知道當(dāng)前 MySQL 的 innodb 行鎖等待情況，例如我們一邊模擬上述報錯場景(模擬頁面操作)，另一邊使用腳本查詢(需要在超時之前查詢，否則超時報錯后就看不到了)。
- /*innodb 行鎖等待腳本*/
- 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)
如上我們可以看到事務(wù) 2 的線程 id 為 76，已經(jīng)被事務(wù) 1，也就是線程 id 為 75 的事務(wù)阻塞了 3s，并且可以看到事務(wù) 1 當(dāng)前執(zhí)行的 SQL 為一個 SELECT。這里也解釋了很多開發(fā)經(jīng)常問我的，為什么 SELECT 也會阻塞其他會話?如果遇到這種情況，那么處理其實非常簡單。需要優(yōu)化這個 SELECT 就好了，實在優(yōu)化不了，把這個查詢?nèi)拥绞聞?wù)外就可以了，甚至都不需要挖掘出整個事務(wù)。上述這個問題模擬，其實就是對應(yīng)第三節(jié)問題產(chǎn)生原因中的第二點(事務(wù)中包含性能較差的查詢 SQL)，下面我們把第一點(程序中非數(shù)據(jù)庫交互操作導(dǎo)致事務(wù)掛起)也模擬下，對比下現(xiàn)象。我們只需要將事務(wù) 1 的過程改成如下即可。
- 事務(wù)1：
- start transaction;
- delete from emp where id = 1;
- select * from emp where id in (select id from emp);
- 等待60s(什么都不要做) --> 模擬接口調(diào)用超時，事務(wù)夯住，隨后再執(zhí)行commit。
- commit;
再次用腳本查看，可以看到現(xiàn)象是有所不同的，不同點在于，阻塞事務(wù)處于 sleep 狀態(tài)，即事務(wù)當(dāng)前并不在跑 SQL。從 DBA 的角度看，這類現(xiàn)象八成就可以斷定是代碼在事務(wù)中嵌入了其他的交互操作導(dǎo)致的事務(wù)掛起(另外也有可能是網(wǎng)絡(luò)問題導(dǎo)致的事務(wù)僵死)，因為程序并不像人，它不會偷懶，不會出現(xiàn)事務(wù)執(zhí)行到一半，休息一會再提交一說。
如果是這類現(xiàn)象的問題，因為本質(zhì)并不是由于 SQL 慢導(dǎo)致的事務(wù)掛起，所以必須要到代碼里去找到對應(yīng)的點，看下到底是在做什么交互操作卡住了。
這里就需要開發(fā)去排查代碼才可以找到源頭，但是唯一可用的信息就是該事務(wù)最后執(zhí)行的一條 SQL，也就是上圖中最后一列，從我之前的經(jīng)驗來看(絕大時候)，開發(fā)很難單從這一條 SQL 就可以找到代碼里具體位置，尤其是當(dāng)這條 SQL 是一條很常見的 SQL，就更為困難!
當(dāng)面對這種情況，就需要 DBA 去挖掘出這個事務(wù)執(zhí)行過的所有 SQL，然后再讓開發(fā)去排查代碼，這樣難度應(yīng)該就小多了。這里就需要用到 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)
- --暫時關(guān)閉general_log
- mysql> set global general_log = 0;
- Query OK, 0 rows affected (0.00 sec)
開啟 general_log 后，手動復(fù)現(xiàn)的時候通過 innodb 行鎖等待腳本查詢結(jié)果中的線程 ID，去 general_log 找到對應(yīng)的事務(wù)分析即可，如下：
根據(jù)線程 ID 可以很輕易的從 general_log 中找到對應(yīng)時間點的事務(wù)操作(實際場景下可能需要通過管道命令過濾)。如上圖所示，事務(wù) 1 與事務(wù) 2 的全部 SQL 都可以找到，再通過這些 SQL 去代碼中找到對應(yīng)的位置即可，比如上圖中線程 ID 為 111 的事務(wù)，執(zhí)行 select * from emp where id in (select id from emp) 后到真正提交，過了 1min 左右，原因要么就是這條 SQL 查詢慢，要么就是代碼在執(zhí)行其他交互操作。
PS：general_log 由于會記錄所有 SQL，所以對 MySQL 性能影響較大，且容易暴漲，所以只在問題排查時暫時開啟，問題排查后，請及時關(guān)閉!
5.2 隨機復(fù)現(xiàn)場景
相較于手動復(fù)現(xiàn)場景，這種場景因為具有隨機性，所以無法一邊模擬報錯，一邊通過腳本查詢到具體的阻塞情況，因此需要通過其他方式來監(jiān)控 MySQL 的阻塞情況。我一般是通過在 Linux 上后臺跑監(jiān)控腳本(innodb_lock_monitor.sh)來記錄 MySQL 阻塞情況，腳本如下：
- #!/bin/bash
- #賬號、密碼、監(jiān)控日志
- 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 命令后臺運行監(jiān)控腳本
- [root@192-168-188-155 ~]# nohup sh innodb_lock_monitor.sh &
- [2] 31464
- nohup: ignoring input and appending output to ‘nohup.out’
- --查看 nohup.out 是否出現(xiàn)報錯
- [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.
- --定時查看監(jiān)控日志是否有輸出(沒有輸出的話，這個日志也不會生成哦！)
- [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)
當(dāng)監(jiān)控日志有輸出阻塞信息時，后續(xù)解決方案就和之前的手動復(fù)現(xiàn)場景一致。
- 如果是事務(wù)卡在慢 SQL，那么就需要優(yōu)化 SQL。
- 如果是事務(wù)掛起，那么就通過 general_log 分析事務(wù)，然后找到具體的代碼位置。
PS：問題排查完成后，請及時關(guān)閉后臺監(jiān)控進程，通過 kill+pid 的方式直接關(guān)閉即可!
六、Performance_Schema
之前的方法感覺不是很方便，因為 general_log 需要訪問服務(wù)器，且過濾分析也較難，需要一定的 MySQL 基礎(chǔ)及 Linux 基礎(chǔ)才適用，因此想尋找一種更為簡便的方法。
6.1 方法介紹
個人想法是利用 MySQL 5.5 開始提供的 performance_schema 性能引擎來進行分析，Performance_Schema 是 MySQL 提供的在系統(tǒng)底層監(jiān)視 MySQL 服務(wù)器性能的一個特性，其提供了大量監(jiān)控項，包括：鎖、IO、事務(wù)、內(nèi)存使用等。
介紹下主要原理：
1. 主要用的表有 2 張 events_transactions_history_long 和 events_statements_history_long。
2. transactions_history_long 會記錄歷史事務(wù)信息，events_statements_history_long 則記錄歷史 SQL。
3. 從 transactions_history_long 中得到回滾事務(wù)的線程 ID，再根據(jù)時間范圍去篩選出可疑的事務(wù)，最后從 events_statements_history_long 得到事務(wù)對應(yīng)的 SQL，從中排查哪個為源頭。
優(yōu)點：
1. 不需要通過 general_log 來獲取事務(wù) SQL。
2. 不需要監(jiān)控腳本來獲取到行鎖等待情況。
3. 只需要訪問 MySQL 就可以實現(xiàn)，而不需要訪問服務(wù)器。
4. 性能開銷較小，且不會暴漲，因為是循環(huán)覆蓋寫入的。
5. 可以知道每條 SQL 的運行時長。
缺點：
1. history_long 相關(guān)表默認(rèn)保留記錄有限，可能會把有用的數(shù)據(jù)刷掉，尤其是在 SQL 運行較多的系統(tǒng)。
2. 如果要加大 history_long 相關(guān)表的最大保留行數(shù)，需要重啟 MySQL，無法在線修改參數(shù)。
3. history_long 相關(guān)表記錄中的時間均為相對時間，也就是距離 MySQL 啟動的時長，看起來不是很方便。
4. history_long 相關(guān)表不會主動記錄行鎖等待的信息，所以只能通過先根據(jù)時間范圍刷選出可疑的事務(wù)，再進一步分析，不如腳本監(jiān)控定位的準(zhǔn)。
- /*開啟performance_schema相關(guān)監(jiān)控項，需要提前開啟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%';
- /*查看回滾事務(wù)SQL，確認(rèn)是否是日志里報錯的事務(wù)*/
- 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'
- /*查看該時間段內(nèi)可疑事務(wù)即超過5s的事務(wù)SQL，這里默認(rèn)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查詢結(jié)果中的線程ID*/
- AND EVENT_ID = 518) /*上述SQL查詢結(jié)果中的事件ID*/
- AND b.TIMER_END > ( SELECT TIMER_END FROM performance_schema.events_transactions_history_long
- WHERE THREAD_ID = 70402 /*上述SQL查詢結(jié)果中的線程ID*/
- AND EVENT_ID = 518) /*上述SQL查詢結(jié)果中的事件ID*/
- ORDER BY a.THREAD_ID
6.2 測試模擬
如果是用這種方法的話，那么就不需要分手動復(fù)現(xiàn)還是隨機復(fù)現(xiàn)了，操作方法都是一樣的，下面模擬下如何操作：
1. 首先通過上述方法開啟 performance_schema 相關(guān)監(jiān)控項，會直接生效，無需重啟 MySQL。
2. 然后復(fù)現(xiàn)問題，這里最好是手動復(fù)現(xiàn)(因為復(fù)現(xiàn)后如果沒有及時查看，監(jiān)控數(shù)據(jù)可能就會被刷掉)，不行的話就只能等待隨機復(fù)現(xiàn)了。
3. 問題復(fù)現(xiàn)后通過上述腳本查詢是否存在回滾事務(wù)(即因為行鎖超時回滾的事務(wù))。
4. 然后根據(jù)回滾事務(wù)的線程 ID 和事件 ID，帶入到最后一個腳本中，查看可疑事務(wù)，進行分析。
這里由于是測試環(huán)境模擬，所以結(jié)果非常了然，項目上實際輸出結(jié)果可能有很多，需要一一分析事務(wù)是否有問題!
七、總結(jié)
實際測試后，發(fā)現(xiàn)通過 performance_schema 來排查行鎖等待超時問題限制其實也比較多，而且最后的分析也是一門技術(shù)活，并不如一開始想象的那么簡單，有點事與愿違了。
通過 performance_schema 排查問題最難處理的有 3 點：
1. 時間問題，相對時間如何轉(zhuǎn)換為絕對時間，這個目前一直找不到好的方法。
2. 不會主動記錄下行鎖等待的信息，所以只能通過時間節(jié)點刷選后進一步分析。
3. 記錄被刷問題，因為是內(nèi)存表，設(shè)置很大容易內(nèi)存溢出，設(shè)置很小就容易被很快刷掉。
