org.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 F a s t C l a s s B y S p r i n g C G L I B FastClassBySpringCGLIB FastClassBySpringCGLIB824241b9.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 F a s t C l a s s B y S p r i n g C G L I B FastClassBySpringCGLIB FastClassBySpringCGLIB824241b9.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 read
mysql tables in use 1, locked 1
LOCK WAIT 4 lock struct(s), heap size 1136, 5 row lock(s), undo log entries 2
MySQL thread id 6264489, OS thread handle 140273305761536, query id 837446998 10.10.59.164 root updating
UPDATE 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 waiting
Record lock, heap no 3 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 8; hex 8000000000000005; asc ;;
1: len 8; hex 8000000000000006; asc ;;
*** (2) TRANSACTION:
TRANSACTION 95146581, ACTIVE 2 sec starting index read
mysql tables in use 1, locked 1
4 lock struct(s), heap size 1136, 5 row lock(s), undo log entries 2
MySQL thread id 6264490, OS thread handle 140280327919360, query id 837446999 10.10.59.164 root updating
UPDATE 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 gap
Record lock, heap no 3 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 8; hex 8000000000000005; asc ;;
1: 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; asc ;;
1: 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 waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 8; hex 8000000000000004; asc ;;
1: len 8; hex 8000000000000005; asc ;;
*** WE ROLL BACK TRANSACTION (2)
关键点总结如下:
1.该库中最近一次死锁发生的时间是什么时候?
4行:2020-07-14 23:34:29 0x7f958f1d5700得知,最近一次死锁发生在 2020-07-14 23:34:29
2.该次死锁导致的两个事务的重要信息?
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 waiting
24行: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 gap
34行: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 waiting
39行:*** WE ROLL BACK TRANSACTION (2)得知,最后回滚的是事务 1
从 12、24、34 行:index idx_user_id of table mall.test_table得知:导致该次死锁的索引为:idx_user_id
3.能知道导致死锁的两个具体 SQL 吗?
不能,产生死锁的情况各式各样,事务中的 SQL 可能不止有两个 SQL,单从死锁日志是没法知道具体原因的,必须要结合业务代码查看事务上下文查看
2. 理论知识
============
排查过程中发现有个特点,影响的都是是线上的大用户。由于当时我很久没看死锁相关的理论知识,因此先去了解下相关死锁的基本知识。
2.1 死锁的条件
=============
-
互斥条件:一个资源每次只能被一个进程使用。
-
占有且等待:一个进程因请求资源而阻塞时,对已获得的资源保持不放。
-
不可强行占有:进程已获得的资源,在未使用完之前,不能强行剥夺。
-
循环等待条件:若干进程之间形成一种头尾相接的循环等待资源关系。
破坏死锁也很简单,四个条件破一个即可。(本案例是破坏的 4)
2.2 数据库的锁类型
===============
数据库的死锁比较复杂,主要是由 Insert、Update(其实在开发中 Delete 或 For Update 是不怎么不考虑的,因为在实际业务代码中我们一般不会有 Delete 或 For Update 的操作,删除都是物理删除,for update 建议少用,除非你知道非用不可)。InnoDB 的锁:
-
共享锁与独占锁(S、X)
-
意向锁
-
记录锁(Record Locks)
-
间隙锁(Gap Locks)
-
Next-Key Locks
-
插入意向锁
-
自增锁
-
空间索引断言锁
这里参考了官网的 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)。具体是哪个主键我们并不清楚。
分享
首先分享一份学习大纲,内容较多,涵盖了互联网行业所有的流行以及核心技术,以截图形式分享:
(亿级流量性能调优实战+一线大厂分布式实战+架构师筑基必备技能+设计思想开源框架解读+性能直线提升架构技术+高效存储让项目性能起飞+分布式扩展到微服务架构…实在是太多了)
其次分享一些技术知识,以截图形式分享一部分:
Tomcat架构解析:
算法训练+高分宝典:
Spring Cloud+Docker微服务实战:
最后分享一波面试资料:
切莫死记硬背,小心面试官直接让你出门右拐
1000道互联网Java面试题:
Java高级架构面试知识整理:
解析:
[外链图片转存中…(img-ZLN91lQ3-1714217260412)]
算法训练+高分宝典:
[外链图片转存中…(img-WEUxVt8n-1714217260413)]
Spring Cloud+Docker微服务实战:
[外链图片转存中…(img-6bbHLthL-1714217260413)]
最后分享一波面试资料:
切莫死记硬背,小心面试官直接让你出门右拐
1000道互联网Java面试题:
[外链图片转存中…(img-GrMLHYVw-1714217260413)]
Java高级架构面试知识整理:
[外链图片转存中…(img-s7BDV8nP-1714217260414)]