[[383006]]

一、大綱

#### 20191219 10:10:10,234 | com.alibaba.druid.filter.logging.Log4jFilter.statementLogError(Log4jFilter.java:152) | ERROR |  {conn-10593, pstmt-38675} execute error. update xxx set xxx = ? , xxx = ?  where RowGuid = ? 
com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Lock wait timeout exceeded; try restarting transaction 

之前在 [如何有效排查解決 MySQL 行鎖等待超時(shí)問(wèn)題] 文章中介紹了如何監(jiān)控解決行鎖超時(shí)報(bào)錯(cuò)，當(dāng)時(shí)介紹的監(jiān)控方案主要是以 shell 腳本 + general_log 來(lái)捕獲行鎖等待信息，后來(lái)感覺(jué)比較麻煩，因此優(yōu)化后改成用 Event + Procedure 的方法定時(shí)在 MySQl 內(nèi)執(zhí)行，將行鎖等待信息記錄到日志表中，并且加入了 pfs 表中的事務(wù)上下文信息，這樣可以省去登陸服務(wù)器執(zhí)行腳本與分析 general_log 的過(guò)程，更加便捷。

因?yàn)橛玫搅?Event 和 performance_schema 下的系統(tǒng)表，所以需要打開(kāi)兩者的配置，pfs 使用默認(rèn)監(jiān)控項(xiàng)就可以，這里主要使用到的是 events_statements_history 表，默認(rèn)會(huì)保留會(huì)話 10 條 SQL。

performance_schema = on 
event_scheduler = 1  

二、步驟

目前該方法僅在 MySQL 5.7 版本使用過(guò)，MySQL 8.0 未測(cè)試。

create database `innodb_monitor`; 

create database `innodb_monitor`;

2.2 創(chuàng)建存儲(chǔ)過(guò)程

use innodb_monitor; 
delimiter ;; 
CREATE PROCEDURE pro_innodb_lock_wait_check() 
BEGIN 
 declare wait_rows int; 
  
set group_concat_max_len = 1024000; 
 
CREATE TABLE IF NOT EXISTS `innodb_lock_wait_log` ( 
  `report_time` datetime DEFAULT NULL, 
  `waiting_id` int(11) DEFAULT NULL, 
  `blocking_id` int(11) DEFAULT NULL, 
  `duration` varchar(50) DEFAULT NULL,   
  `state` varchar(50) DEFAULT NULL, 
  `waiting_query` longtext DEFAULT NULL, 
  `blocking_current_query` longtext DEFAULT NULL, 
  `blocking_thd_last_query` longtext, 
  `thread_id` int(11) DEFAULT NULL 
); 
 
 select count(*) into wait_rows from information_schema.innodb_lock_waits ; 
 
 if wait_rows > 0 THEN  
   insert into `innodb_lock_wait_log`  SELECT now(),r.trx_mysql_thread_id waiting_id,b.trx_mysql_thread_id blocking_id,concat(timestampdiff(SECOND,r.trx_wait_started,CURRENT_TIMESTAMP()),'s') AS duration, 
     t.processlist_command state,r.trx_query waiting_query,b.trx_query blocking_current_query,group_concat(left(h.sql_text,10000) order by h.TIMER_START DESC SEPARATOR ';\n') As blocking_thd_query_history,thread_id 
    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 
     LEFT JOIN performance_schema.threads t on t.processlist_id = b.trx_mysql_thread_id LEFT JOIN performance_schema.events_statements_history h USING(thread_id) group by thread_id,r.trx_id order by r.trx_wait_started; 
  
 end if; 
END 
;; 

2.3 創(chuàng)建事件

事件 每隔 5 秒 (通常等于 innodb_lock_wait_timeout 的值)執(zhí)行一次，持續(xù)監(jiān)控 7 天，結(jié)束后會(huì)自動(dòng)刪除事件，也可以自定義保留時(shí)長(zhǎng)。

use innodb_monitor; 
delimiter ;; 
CREATE EVENT `event_innodb_lock_wait_check` 
ON SCHEDULE EVERY 5 SECOND  
 STARTS CURRENT_TIMESTAMP  
 ENDS CURRENT_TIMESTAMP + INTERVAL 7 DAY 
ON COMPLETION NOT PRESERVE 
ENABLE 
DO 
call pro_innodb_lock_wait_check(); 
;; 

2.4 事件啟停

--1為全局開(kāi)啟事件,0為全局關(guān)閉 
mysql > SET GLOBAL event_scheduler = 1; 
 
--臨時(shí)關(guān)閉事件 
mysql > ALTER EVENT event_innodb_lock_wait_check DISABLE; 
 
--關(guān)閉開(kāi)啟事件 
mysql > ALTER EVENT event_innodb_lock_wait_check  ENABLE; 

三、日志表

再根據(jù)應(yīng)用日志報(bào)錯(cuò)時(shí)間點(diǎn)及 SQL 分析 innodb_lock_wait_log 表。其中主要有 2 種場(chǎng)景：

1. blocking_current_query 不為空，說(shuō)明阻塞事務(wù)處于運(yùn)行狀態(tài)，這時(shí)候需要分析當(dāng)前運(yùn)行 SQL 是否存在性能問(wèn)題。
2. blocking_current_query 為空，state 為 Sleep，此時(shí)阻塞事務(wù)處于掛起狀態(tài)，即不再運(yùn)行 SQL，此時(shí)需要通過(guò)分析 blocking_thd_last_query 分析事務(wù)上下文，注意該列中的 SQL 為時(shí)間降序，即從下往上執(zhí)行。