江苏龙网

  1. 首页 > 人文 > >

mysql|线上频出MySQL死锁问题！分享一下教科书般的排查和分析过程


1. 日志
1.1 业务日志
一直平稳运行大半年的代码 ， 突然在最近几天频出现死锁异常 ， 业务机器大概每一两天在业务高峰期发生一次如下的业务日志：

INFO 57553 --- [ConsumerThread2] org.example.controller.TestController : 全局链路跟踪id:2的日志：[TransactionReqVO(userId=4, money=4), TransactionReqVO(userId=2, money=2), TransactionReqVO(userId=5, money=5)] INFO 57553 --- [ConsumerThread1] org.example.controller.TestController : 全局链路跟踪id:1的日志：[TransactionReqVO(userId=5, money=5), TransactionReqVO(userId=1, money=1), TransactionReqVO(userId=4, money=4)]ERROR 57553 --- [ConsumerThread2] org.example.controller.TestController : 全局链路跟踪id:2的异常：### Error updating database. Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock try restarting transaction### The error may exist in org/example/mapper/TestTableMapper.java (best guess)### The error may involve org.example.mapper.TestTableMapper.update-Inline### The error occurred while setting parameters### SQL: UPDATE test_table SET money = money + ? WHERE user_id = ?### Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock try restarting transaction Deadlock found when trying to get lock try restarting transaction nested exception is com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock try restarting transactionorg.springframework.dao.DeadlockLoserDataAccessException: ### Error updating database. Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock try restarting transaction### The error may exist in org/example/mapper/TestTableMapper.java (best guess)### The error may involve org.example.mapper.TestTableMapper.update-Inline### The error occurred while setting parameters### SQL: UPDATE test_table SET money = money + ? WHERE user_id = ?### Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock try restarting transaction Deadlock found when trying to get lock try restarting transaction nested exception is com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock try restarting transaction at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.doTranslate(SQLErrorCodeSQLExceptionTranslator.java:266) ~[spring-jdbc-5.0.13.RELEASE.jar:5.0.13.RELEASE] at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:72) ~[spring-jdbc-5.0.13.RELEASE.jar:5.0.13.RELEASE] at org.mybatis.spring.MyBatisExceptionTranslator.translateExceptionIfPossible(MyBatisExceptionTranslator.java:73) ~[mybatis-spring-2.0.1.jar:2.0.1] at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:446) ~[mybatis-spring-2.0.1.jar:2.0.1] at com.sun.proxy.$Proxy59.update(Unknown Source) ~[na:na] at org.mybatis.spring.SqlSessionTemplate.update(SqlSessionTemplate.java:294) ~[mybatis-spring-2.0.1.jar:2.0.1] at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:67) ~[mybatis-3.5.1.jar:3.5.1] at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:58) ~[mybatis-3.5.1.jar:3.5.1] at com.sun.proxy.$Proxy62.update(Unknown Source) ~[na:na] at org.example.service.impl.TestServiceImpl.update(TestServiceImpl.java:16) ~[classes/:na] at org.example.manager.impl.BizManagerImpl.transactionMoney(BizManagerImpl.java:25) ~[classes/:na] at org.example.manager.impl.BizManagerImpl$$FastClassBySpringCGLIB$$824241b9.invoke(
) ~[classes/:na]
Deadlock 非常显眼 ， 说明业务上出现了死锁 ， 肯定是业务上有问题 。 但是该业务代码一直运行了大半年 ， 查看 Git 记录也发现最近没人动该业务相关代码 ， 说明该业务之前就可能有问题 ， 只是最近才达到了触发这种异常的条件 。
对该日志做个简单的总结：
1.这是什么错误日志？
8行：### SQL: UPDATE test_table SET money = money + ? WHERE user_id = ?9行：### Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock try restarting transaction从第 8~9 行可以得知 ， 该错误是数据库的错误 ， 是死锁错误异常而导致的回滚 ， 关键 SQL 是：UPDATE test_table SET money = money + ? WHERE user_id = ?
2.核心错误的调用方法是哪个 ， 即事务开始的方法是哪个?
30行：at org.example.manager.impl.BizManagerImpl.transactionMoney(BizManagerImpl.java:25) ~[classes/:na] 31行：at org.example.manager.impl.BizManagerImpl$$FastClassBySpringCGLIB$$824241b9.invoke() ~[classes/:na]过滤了 jdk 类、spring 类、mybatis 类后 ， 得到核心的业务错误代码（30~31 行） ， 31 行为 Spring 的代理执行 ， 30 行才是真正最开始执行业务代码：BizManagerImpl.transactionMoney
1.2 数据库死锁日志
接着去查看该库对应的数据库死锁日志 ， 使用命令：show innodb engine status ， 过滤掉非重要的日志后如下：
------------------------LATEST DETECTED DEADLOCK------------------------2020-07-14 23:34:29 0x7f958f1d5700*** (1) TRANSACTION:TRANSACTION 95146580, ACTIVE 2 sec starting index readmysql tables in use 1, locked 1LOCK WAIT 4 lock struct(s), heap size 1136, 5 row lock(s), undo log entries 2MySQL thread id 6264489, OS thread handle 140273305761536, query id 837446998 10.10.59.164 root updatingUPDATE test_table SET money = money + 5 WHERE user_id = 5*** (1) WAITING FOR THIS LOCK TO BE GRANTED:RECORD LOCKS space id 71816 page no 4 n bits 80 index idx_user_id of table `mall`.`test_table` trx id 95146580 lock_mode X locks rec but not gap waitingRecord lock, heap no 3 PHYSICAL RECORD: n_fields 2 compact format info bits 0 0: len 8 hex 8000000000000005 asc1: len 8 hex 8000000000000006 asc *** (2) TRANSACTION:TRANSACTION 95146581, ACTIVE 2 sec starting index readmysql tables in use 1, locked 14 lock struct(s), heap size 1136, 5 row lock(s), undo log entries 2MySQL thread id 6264490, OS thread handle 140280327919360, query id 837446999 10.10.59.164 root updatingUPDATE test_table SET money = money + 4 WHERE user_id = 4*** (2) HOLDS THE LOCK(S):RECORD LOCKS space id 71816 page no 4 n bits 80 index idx_user_id of table `mall`.`test_table` trx id 95146581 lock_mode X locks rec but not gapRecord lock, heap no 3 PHYSICAL RECORD: n_fields 2 compact format info bits 0 0: len 8 hex 8000000000000005 asc1: len 8 hex 8000000000000006 asc Record lock, heap no 5 PHYSICAL RECORD: n_fields 2 compact format info bits 0 0: len 8 hex 8000000000000001 asc1: len 8 hex 8000000000000002 asc *** (2) WAITING FOR THIS LOCK TO BE GRANTED:RECORD LOCKS space id 71816 page no 4 n bits 80 index idx_user_id of table `mall`.`test_table` trx id 95146581 lock_mode X locks rec but not gap waitingRecord lock, heap no 2 PHYSICAL RECORD: n_fields 2 compact format info bits 0 0: len 8 hex 8000000000000004 asc1: len 8 hex 8000000000000005 asc *** WE ROLL BACK TRANSACTION (2)
关键点总结如下：
1.该库中最近一次死锁发生的时间是什么时候？
4行：2020-07-14 23:34:29 0x7f958f1d5700得知 ， 最近一次死锁发生在 2020-07-14 23:34:292.该次死锁导致的两个事务的重要信息？
12行：RECORD LOCKS space id 71816 page no 4 n bits 80 index idx_user_id of table mall.test_table trx id 95146580 lock_mode X locks rec but not gap waiting得知 ， 事务 1 等待的锁为：lock_mode X locks rec but not gap waiting24行：RECORD LOCKS space id 71816 page no 4 n bits 80 index idx_user_id of table mall.test_table trx id 95146581 lock_mode X locks rec but not gap得知 ， 事务 2 持有的锁为：lock_mode X locks rec but not gap34行：RECORD LOCKS space id 71816 page no 4 n bits 80 index idx_user_id of table mall.test_table trx id 95146581 lock_mode X locks rec but not gap waiting得知 ， 事务 2 等待的锁为：lock_mode X locks rec but not gap waiting39行：*** WE ROLL BACK TRANSACTION (2)得知 ， 最后回滚的是事物 1从 12、24、34 行：index idx_user_id of table mall.test_table得知：导致该次死锁的索引为：idx_user_id3.能知道导致死锁的两个具体 SQL 吗？
不能 ， 产生死锁的情况各式各样 ， 事务中的 SQL 可能不止有两个 SQL ， 单从死锁日志是没法知道具体原因的 ， 必须要结合业务代码查看事务上下文查看2. 理论知识
排查过程中发现有个特点 ， 影响的都是是线上的大用户 。 由于当时我很久没看死锁相关的理论知识 ， 因此先去了解下相关死锁的基本知识 。
2.1 死锁的条件
1. 互斥条件：一个资源每次只能被一个进程使用 。
2. 占有且等待：一个进程因请求资源而阻塞时 ， 对已获得的资源保持不放 。
3. 不可强行占有：进程已获得的资源 ， 在未使用完之前 ， 不能强行剥夺 。
4. 循环等待条件：若干进程之间形成一种头尾相接的循环等待资源关系 。
破坏死锁也很简单 ， 四个条件破一个即可 。 （本案例是破坏的 4）
2.2 数据库的锁类型
数据库的死锁比较复杂 ， 主要是由 Insert、Update（其实在开发中 Delete 或 For Update 是不怎么不考虑的 ， 因为在实际业务代码中我们一般不会有 Delete 或 For Update 的操作 ， 删除都是物理删除 ， for update 建议少用 ， 除非你知道非用不可） 。 InnoDB 的锁：
1. 共享锁与独占锁（S、X）
2. 意向锁
3. 记录锁（Record Locks）
4. 间隙锁（Gap Locks）
5. Next-Key Locks
6. 插入意向锁
7. 自增锁
8. 空间索引断言锁
这里参考了官网的 Innodb 锁分类 ， 从死锁日志的 lock_mode X locks rec but not gap， 大致能知道 ， 这里可能涉及了 X 锁、记录锁、间隙锁（但是有个 not ， 说明不涉及） 。
3. 从死锁日志分析
分析之前先得到该表的建表语句：show create table test_table：
CREATE TABLE `test_table` ( `id` bigint(20) NOT NULL AUTO_INCREMENT, `money` bigint(20) NOT NULL, `user_id` bigint(20) NOT NULL, PRIMARY KEY (`id`), KEY `idx_user_id` (`user_id`)) ENGINE=InnoDB AUTO_INCREMENT=5 DEFAULT CHARSET=utf8
接着结合死锁日志、锁的种类、建表语句得出以下模糊的结论：
1.从死锁日志的 10、12 行结合建表索引得知
10行：UPDATE test_table SET money = money + 5 WHERE user_id = 512行：RECORD LOCKS space id 71816 page no 4 n bits 80 index idx_user_id of table mall.test_table trx id 95146580事务1的 UPDATE test_table SET money = money + 5 WHERE user_id = 5 语句在等待锁：它通过普通索引 idx_user_id 更新 ， 先获取了 user_id=5 的 X 锁 ， 接着去申请对应行的主键（Record Lock）的行锁但是被阻塞（waiting） ， 并不包括间隙锁（not gap） 。 具体是哪个主键我们并不清楚 。
2.从死锁日志的 22、24 行结合建表索引得知
22行：UPDATE test_table SET money = money + 4 WHERE user_id = 424行：Record lock, heap no 3 PHYSICAL RECORD: n_fields 2 compact format info bits 0事务2的 UPDATE test_table SET money = money + 4 WHERE user_id = 4 语句在持有锁：它通过普通索引 idx_user_id 更新 ， 先获取了 user_id=4 的 X 锁 ， 接着去申请对应行的主键（Record Lock）的行锁成功了 ， 并不包括间隙锁（not gap） 。 具体是成功的哪个主键我们并不清楚 。
3.从死锁日志的 22、34 行结合建表索引得知
22行：UPDATE test_table SET money = money + 4 WHERE user_id = 434行：RECORD LOCKS space id 71816 page no 4 n bits 80 index idx_user_id of table mall.test_table trx id 95146581 lock_mode X locks rec but not gap waiting事务2的 UPDATE test_table SET money = money + 4 WHERE user_id = 4 语句在等待锁：它通过普通索引 idx_user_id 更新 ， 先获取了 user_id=4 的 X 锁 ， 接着去申请对应行的主键（Record Lock）的行锁但是被阻塞（waiting） ， 并不包括间隙锁（not gap） 。 具体是哪个主键我们并不清楚 。
模糊结论肯定是有问题的 ， 最大的问题在于导致的 SQL 语句不正确 ， 即：死锁的原因是真实的 ， 但是具体是因为哪些 SQL 导致的死锁是不清楚的 。 接着我们整理得到了以下可能有问题的表格：
mysql|线上频出MySQL死锁问题！分享一下教科书般的排查和分析过程
本文插图

可以得知 ， 其实单从死锁日志分析是比较片面的 ， 因为 user_id 为 4、5 这两个 update 操作是不会有互相阻塞的问题 ， 肯定是有别的 SQL 因此 ， 我们需要额外从业务日志分析才能还原完整的现场 。
4. 从业务日志分析
从死锁日志是不能完全知道导致的关键 SQL 和故障现场的整体流程 ， 因此我们要借助业务日志来完成最后对故障现场的分析：通过前面对业务日志的分析 ， 我们知道最关键的调用方法是 BizManagerImpl.transactionMoney ， 查看对应源码：
@Override@Transactionalpublic boolean transactionMoney(List throws Exception { for (TransactionReqVO transactionReqVO : transactionReqVOList) { // 模拟业务操作 Thread.sleep(1000) int updateCount = testTableService.update(transactionReqVO.getUserId(), transactionReqVO.getMoney()) if (updateCount == 0) { log.error("转账异常：" + transactionReqVO) } } return true}
transactionReqVOList)
可以知道 ， 应该是 for 循环事务的问题 ， 但是具体是哪些 user_id 是不清楚的 ， 接着我们查看业务日志的上下文 ， 通过全链路 traceId（模拟） 做搜索 ， 得到以下的日志：
[ConsumerThread2] org.example.controller.TestController : 全局链路跟踪id:2的日志：[TransactionReqVO(userId=4, money=4), TransactionReqVO(userId=2, money=2), TransactionReqVO(userId=5, money=5)][ConsumerThread1] org.example.controller.TestController : 全局链路跟踪id:1的日志：[TransactionReqVO(userId=5, money=5), TransactionReqVO(userId=1, money=1), TransactionReqVO(userId=4, money=4)]
分析到这一步 ， 我们已经可以还原死锁场景了 ， 事务流程图如下：
mysql|线上频出MySQL死锁问题！分享一下教科书般的排查和分析过程
本文插图

5. 业务日志、死锁日志结合分析
将死锁日志分析得出的不正确表格加上业务日志分析得出正确表格 ， 我们得出最终带有理解的最终正确的事务表格：
mysql|线上频出MySQL死锁问题！分享一下教科书般的排查和分析过程
本文插图

可以知道 ， 其实死锁日志的 SQL 是模糊的 ， 但是原因是正确的 ， 至于具体是哪些 SQL 导致的死锁 ， 是需要从业务日志来判定 。
6. 善后
模拟出了事务2的场景 ， 我们就可以对回滚的 SQL 执行 ， 来人工修复受到影响的用户数据（客户第一） 。 也可以知道其实 transactionMoney() 方法不应该加事务 ， 因为该业务场景每个用户的更新是独立的不应该互相受到影响 ， 但是当某条更新失败时 ， 我们也要打印对应的日志 。
这里我们就知道为什么之前大半年都没问题 ， 最近才频发这种异常 ， 因为只有当两个事务同时执行 ， 并且两个事务中包含了相同的两个或两个以上的 user_id 才会可能触发该异常 。 而这种 user_id 都是所谓的大用户 ， 像该示例中的 user_id 为 1、2 是小用户 ， 虽然它们也受到了影响 ， 但是频率是没有 user_id 为 4、5 这种大用户高的 。
在实际的业务场景也证实了这点 ， 不仅是发生故障的时间是集中在高峰期 ， 而且发生故障的用户也经常有那几个熟面孔 ， 经过后面复盘 ， 这几个熟面孔用户也就是我们所说的”大用户“（业务操作频率高的用户） 。
7. 模拟项目源码
为了模拟真实场景中的方法调用（消息接收调用执行） ， 使用了线程来模拟 。 并且使用线程睡眠来保证每个事务执行够长 ， 来让每次模拟执行都出现异常 。
mysql|线上频出MySQL死锁问题！分享一下教科书般的排查和分析过程
本文插图

项目结构比较简单 ，Controller -&gt Manager -&gt Service -&gt Mapper -&gt DB ， 执行 curl "localhost:8080/test/consumer" 后 ， 查看命令行输出即可看到业务异常日志 。
对应的死锁日志需要到对应的数据库执行：show engine innodb status 后可看到 。
8. 最后
中间查阅了很多资料 ， 发现有个项目总结了所有的死锁日志对应的可能 SQL：https://github.com/aneasystone/mysql-deadlocks ， 里面也讲解了加锁的各个细节过程 ， 是非常值得一看的 。 以下为该项目的部分截图：
mysql|线上频出MySQL死锁问题！分享一下教科书般的排查和分析过程
本文插图

当遇到复杂的业务场景 ， 尤其是不熟悉的时候 ， 这个是一个很好的参考资料 。
业务日志记录、全链路跟踪是非常非常重要的声明：转载此文是出于传递更多信息之目的 。 若有来源标注错误或侵犯了您的合法权益 ， 请作者持权属证明与本网联系 ， 我们将及时更正、删除 ， 谢谢 。邮箱地址：newmedia@xxcb.cn
【mysql|线上频出MySQL死锁问题！分享一下教科书般的排查和分析过程】


    推荐阅读


    上一篇：明星八卦|娱巴讲八卦：李现，杨紫，罗云熙恋情，孙俪，王一博，杨超越

    下一篇：产业园|?高新区泊鹭航空产业园备案为B类机场！成为菏泽首个建成运营的通用机场