作者：xuty
本文来源：原创投稿
*爱可生开源社区出品，原创内容未经授权不得随意使用，转载请联系小编并注明来源。
一、背景
#### 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 行锁等待脚本*/
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：
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 基础才适用，因此想寻找一种更为简便的方法。
介绍下主要原理：
优点：
缺点：
/*开启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 来排查行锁等待超时问题限制其实也比较多，而且最后的分析也是一门技术活，并不如一开始想象的那么简单，有点事与愿违了。