记一次MySQL死锁排查

背景

昨天领导说有个现场的数据库定时任务M执行好像有问题，应该往数据库表B插入8000条数据的，实际上只插入了4000条，然后同事顺便提了一下他往插入的这个表B加了一个索引

排查过程

1. 检查定时任务

先查了一下定时任务M的执行时间，定时任务是7天执行一次，在半夜2点执行，上一次执行时间是2023-06-08 02:00:00，那说明作业时正常执行的

SELECT * FROM information_schema.`EVENTS`

2. 查看定时任务内容

作业正常执行，那就得分析一下定时任务内容，定时任务内容很简单，就是调用了存储过程routineA

CALL routineA();

3. 查看存储过程内容

存储过程做了这样一个逻辑，做了一个循环，从A表中查出符合条件的数据，根据获得的数据循环往B表插入

4. 初步分析

因为插入的顺序和查出的顺序的是一致的，我就想是不是在某个特殊的数据上有问题，我就找到B表中最后一笔插入的表号（唯一值），去A表中看看对应的位置，但是发现应该插入的下一条数据也是很正常的数据，没有异常。
于是问题就转变成了，程序突然停止，可能是重启了数据库，服务器，或者是死锁？

5. 排查是否有死锁

检查了mysql的错误日志mysqld.log，发现在执行定时任务M的时候确实发生了死锁，但是没看到死锁的详细信息，查了一下发现是有一个参数没启用

SHOW VARIABLES LIKE '%innodb_print_all_deadlocks%';

# my.cnf 开启打印死锁详细信息
innodb_print_all_deadlocks = ON

然后刚好业务需要重新执行任务，去补上缺失的4000条数据，于是重新执行了一次存储过程
这里是发现了一些更多的东西
重新执行一半仍然死锁，而且发现插入B表的速度很慢，大概一秒几十条

6. 第二次分析

重新查看日志发现造成死锁的原因
是在循环插入的过程中，遇到了另外的定时任务N执行的语句，导致了死锁

-- 这里根据mysqld.log日志找到造成死锁的2条语句
-- 去系统或者存储过程定位到是哪个地方执行的
SELECT * FROM information_schema.`ROUTINES` WHERE ROUTINE_DEFINITION LIKE '%xxxx%';

而且出现了很多record lock行锁，这是导致执行速度很慢的原因
但是之前任务都是正常的，突然出现问题，这其中只有同事加的那个索引影响了
于是索引删除，重新执行存储过程插入
发现原先执行很慢的现在异常快不到1s就执行完了

7. 初步总结

加了索引以后，在频繁插入的过程中造成了行锁
导致插入速度变慢
变慢以后拉长了整体执行时间
然后遇上了另外一个定时任务N执行
造成了死锁，而且是必然造成

8. 定性

根本原因在于另外一个定时任务N的写法有问题，导致占用了大量的行锁，这根据mysqld.log的死锁日志看得出来
定时任务的写法是

UPDATE B SET status = 1 WHERE id IN (
    子查询
);

通过对这个语句explain后发现
子查询效率慢，没有正确使用索引，而且因为使用in去update，导致也无法走索引
因为改成了JOIN关联，加上合适的索引
再次EXPLAIN发现索引命中，效率提升很多
即使在存储过程插入B表的时候拉长了时间碰上这个定时任务，也不会造成死锁了