[[323417]]

一、背景

 

#### 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 的同學或多或少應該都遇到過，專業一點來說，這個報錯我們稱之為鎖等待超時。根據鎖的類型主要細分為：

• 行鎖等待超時

當 SQL 因為等待行鎖而超時，那么就為行鎖等待超時，常在多并發事務場景下出現。

• 元數據鎖等待超時

當 SQL 因為等待元數據鎖而超時，那么就為元數據鎖等待超時，常在 DDL 操作期間出現。

本文僅介紹如何有效解決行鎖等待超時，因為大多數項目都是此類錯誤，元數據鎖等待超時則不涉及講解。

二、行鎖的等待

在介紹如何解決行鎖等待問題前，先簡單介紹下這類問題產生的原因。產生原因簡述：當多個事務同時去操作(增刪改)某一行數據的時候，MySQL 為了維護 ACID 特性，就會用鎖的形式來防止多個事務同時操作某一行數據，避免數據不一致。只有分配到行鎖的事務才有權力操作該數據行，直到該事務結束，才釋放行鎖，而其他沒有分配到行鎖的事務就會產生行鎖等待。如果等待時間超過了配置值(也就是 innodb_lock_wait_timeout 參數的值，個人習慣配置成 5s，MySQL 官方默認為 50s)，則會拋出行鎖等待超時錯誤。

 

如上圖所示，事務 A 與事務 B 同時會去 Insert 一條主鍵值為 1 的數據，由于事務 A 首先獲取了主鍵值為 1 的行鎖，導致事務 B 因無法獲取行鎖而產生等待，等到事務 A 提交后，事務 B 才獲取該行鎖，完成提交。這里強調的是行鎖的概念，雖然事務 B 重復插入了主鍵，但是在獲取行鎖之前，事務一直是處于行鎖等待的狀態，只有獲取行鎖后，才會報主鍵沖突的錯誤。當然這種 Insert 行鎖沖突的問題比較少見，只有在大量并發插入場景下才會出現，項目上真正常見的是 update&delete 之間行鎖等待，這里只是用于示例，原理都是相同的。

三、產生的原因

根據我之前接觸到的此類問題，大致可以分為以下幾種原因：

1. 程序中非數據庫交互操作導致事務掛起

將接口調用或者文件操作等這一類非數據庫交互操作嵌入在 SQL 事務代碼之中，那么整個事務很有可能因此掛起(接口不通等待超時或是上傳下載大附件)。

2. 事務中包含性能較差的查詢SQL

事務中存在慢查詢，導致同一個事務中的其他 DML 無法及時釋放占用的行鎖，引起行鎖等待。

3. 單個事務中包含大量 SQL

通常是由于在事務代碼中加入 for 循環導致，雖然單個 SQL 運行很快，但是 SQL 數量一大，事務就會很慢。

4. 級聯更新 SQL 執行時間較久

這類 SQL 容易讓人產生錯覺，例如：update A set ... where ...in (select B) 這類級聯更新，不僅會占用 A 表上的行鎖，也會占用 B 表上的行鎖，當 SQL 執行較久時，很容易引起 B 表上的行鎖等待。

5. 磁盤問題導致的事務掛起

極少出現的情形，比如存儲突然離線，SQL 執行會卡在內核調用磁盤的步驟上，一直等待，事務無法提交。綜上可以看出，如果事務長時間未提交，且事務中包含了 DML 操作，那么就有可能產生行鎖等待，引起報錯。

四、定位難點當

web 日志中出現行鎖超時錯誤后，很多開發都會找我來排查問題，這里說下問題定位的難點!

1. MySQL 本身不會主動記錄行鎖等待的相關信息，所以無法有效的進行事后分析。

2. 鎖爭用原因有多種，很難在事后判斷到底是哪一類問題場景，尤其是事后無法復現問題的時候。

3. 找到問題 SQL 后，開發無法有效從代碼中挖掘出完整的事務，這也和公司框架-產品-項目的架構有關，需要靠 DBA 事后采集完整的事務 SQL 才可以進行分析。

五、常用方法

先介紹下個人通常是如何解決此類問題的， 這里問題解決的前提是問題可以復現，只要不是突然出現一次，之后再也不出現，一般都是可以找到問題源頭的。

這里問題復現分為兩種情景：

1. 手動復現

只要按照一定的操作，就可以復現報錯，這種場景較簡單!

2. 隨機復現

不知道何時會突然報錯，無法手動復現，這種場景較難!

下面先寫下統一的模擬場景，用于復現行鎖超時問題，便于大家理解：

 

--表結構 
 
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 行鎖等待腳本*/ 
 
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) 

 

如上我們可以看到事務 2 的線程 id 為 76，已經被事務 1，也就是線程 id 為 75 的事務阻塞了 3s，并且可以看到事務 1 當前執行的 SQL 為一個 SELECT。這里也解釋了很多開發經常問我的，為什么 SELECT 也會阻塞其他會話?如果遇到這種情況，那么處理其實非常簡單。需要優化這個 SELECT 就好了，實在優化不了，把這個查詢扔到事務外就可以了，甚至都不需要挖掘出整個事務。上述這個問題模擬，其實就是對應第三節問題產生原因中的第二點(事務中包含性能較差的查詢 SQL)，下面我們把第一點(程序中非數據庫交互操作導致事務掛起)也模擬下，對比下現象。我們只需要將事務 1 的過程改成如下即可。

 

 

 

事務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 找到對應的事務分析即可，如下：

 

 

根據線程 ID 可以很輕易的從 general_log 中找到對應時間點的事務操作(實際場景下可能需要通過管道命令過濾)。如上圖所示，事務 1 與事務 2 的全部 SQL 都可以找到，再通過這些 SQL 去代碼中找到對應的位置即可，比如上圖中線程 ID 為 111 的事務，執行 select * from emp where id in (select id from emp) 后到真正提交，過了 1min 左右，原因要么就是這條 SQL 查詢慢，要么就是代碼在執行其他交互操作。

PS：general_log 由于會記錄所有 SQL，所以對 MySQL 性能影響較大，且容易暴漲，所以只在問題排查時暫時開啟，問題排查后，請及時關閉!

5.2 隨機復現場景

相較于手動復現場景，這種場景因為具有隨機性，所以無法一邊模擬報錯，一邊通過腳本查詢到具體的阻塞情況，因此需要通過其他方式來監控 MySQL 的阻塞情況。我一般是通過在 Linux 上后臺跑監控腳本(innodb_lock_monitor.sh)來記錄 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 基礎才適用，因此想尋找一種更為簡便的方法。

6.1 方法介紹

個人想法是利用 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 測試模擬

如果是用這種方法的話，那么就不需要分手動復現還是隨機復現了，操作方法都是一樣的，下面模擬下如何操作：

1. 首先通過上述方法開啟 performance_schema 相關監控項，會直接生效，無需重啟 MySQL。

2. 然后復現問題，這里最好是手動復現(因為復現后如果沒有及時查看，監控數據可能就會被刷掉)，不行的話就只能等待隨機復現了。

3. 問題復現后通過上述腳本查詢是否存在回滾事務(即因為行鎖超時回滾的事務)。

 

4. 然后根據回滾事務的線程 ID 和事件 ID，帶入到最后一個腳本中，查看可疑事務，進行分析。

 

這里由于是測試環境模擬，所以結果非常了然，項目上實際輸出結果可能有很多，需要一一分析事務是否有問題!

七、總結

實際測試后，發現通過 performance_schema 來排查行鎖等待超時問題限制其實也比較多，而且最后的分析也是一門技術活，并不如一開始想象的那么簡單，有點事與愿違了。

通過 performance_schema 排查問題最難處理的有 3 點：

1. 時間問題，相對時間如何轉換為絕對時間，這個目前一直找不到好的方法。

2. 不會主動記錄下行鎖等待的信息，所以只能通過時間節點刷選后進一步分析。

3. 記錄被刷問題，因為是內存表，設置很大容易內存溢出，設置很小就容易被很快刷掉。