背景:
今天在进行消息中心的业务相关测试时,发现一个mysql的异常,异常如下
Deadlock found when trying to get lock; try restarting transaction
从中我们不难理解,这是Mysql死锁DeadLock的原因.下面我们开始对其进行排查
环境:
mysql的user_info表结构如下
CREATE TABLE `msg_user_record` (
`id` int(11) unsigned NOT NULL AUTO_INCREMENT,
`user_id` varchar(32) DEFAULT NULL COMMENT '用户id',
`cat_code` varchar(32) DEFAULT NULL COMMENT '分类标识',
`cat_name` varchar(32) DEFAULT NULL COMMENT '分类名称',
`msg_id` varchar(32) DEFAULT NULL COMMENT '消息ID',
`read_status` bit(1) NOT NULL DEFAULT b'0' COMMENT '已读状态',
`read_time` datetime DEFAULT NULL COMMENT '已读时间',
`receive_status` bit(1) NOT NULL DEFAULT b'0' COMMENT '已收状态',
`receive_time` datetime DEFAULT NULL COMMENT '已收时间',
`created_at` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP COMMENT '创建时间',
`updated_at` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP COMMENT '更新时间',
PRIMARY KEY (`id`) USING BTREE,
KEY `user_idx` (`user_id`) USING BTREE,
KEY `cat_code` (`cat_code`) USING BTREE,
KEY `msg_id` (`msg_id`) USING BTREE
) ENGINE=InnoDB AUTO_INCREMENT=45843 DEFAULT CHARSET=utf8mb4 COMMENT='用户消息记录表';
其中共有19548条数据
业务场景如下:
用户在app端点击阅读某条消息时,要求同分类下所有消息都设置为已读read_status=1;
所以有两个sql事务被并发执行(只讨论问题出现原因,为什么是两条sql别和我杠😂).
事务1:
update msg_user_record set read_status = 1, read_time = now()
where user_id = #{userId} and msg_id = #{msgId} and read_status=0;
事务2:
update msg_user_record set read_status = 1, read_time = now()
where user_id = #{userId} and cat_code = #{catCode} and read_status=0;
两个事务在高并执行时,就会出现
2020-09-25 11:41:29.979 DEBUG 19658 --- [ Thread-15] c.w.d.m.M.categoryRead : ==> Preparing: update msg_user_record set read_status = 1, read_time = now() where user_id = ? and cat_code = ? and read_status=0;
2020-09-25 11:41:29.979 DEBUG 19658 --- [ Thread-16] c.w.d.m.MsgUserRecordMapper.msgRead : ==> Preparing: update msg_user_record set read_status = 1, read_time = now() where user_id = ? and msg_id = ? and read_status=0;
2020-09-25 11:41:29.979 DEBUG 19658 --- [ Thread-15] c.w.d.m.M.categoryRead : ==> Parameters: 54504790680291242936083(String), cstmbus(String)
2020-09-25 11:41:29.979 DEBUG 19658 --- [ Thread-16] c.w.d.m.MsgUserRecordMapper.msgRead : ==> Parameters: 54504790680291242936083(String), M4805831019234066910(String)
2020-09-25 11:41:29.982 DEBUG 19658 --- [ Thread-16] c.w.d.m.MsgUserRecordMapper.msgRead : <== Updates: 0
2020-09-25 11:41:29.988 DEBUG 19658 --- [ Thread-15] c.w.d.m.M.categoryRead : <== Updates: 0
2020-09-25 11:41:45.815 DEBUG 19658 --- [ Thread-18] c.w.d.m.MsgUserRecordMapper.msgRead : ==> Preparing: update msg_user_record set read_status = 1, read_time = now() where user_id = ? and msg_id = ? and read_status=0;
2020-09-25 11:41:45.815 DEBUG 19658 --- [ Thread-17] c.w.d.m.M.categoryRead : ==> Preparing: update msg_user_record set read_status = 1, read_time = now() where user_id = ? and cat_code = ? and read_status=0;
2020-09-25 11:41:45.816 DEBUG 19658 --- [ Thread-17] c.w.d.m.M.categoryRead : ==> Parameters: 54504790680291242936083(String), cstmbus(String)
2020-09-25 11:41:45.816 DEBUG 19658 --- [ Thread-18] c.w.d.m.MsgUserRecordMapper.msgRead : ==> Parameters: 54504790680291242936083(String), M4805831019234066910(String)
2020-09-25 11:41:45.826 DEBUG 19658 --- [ Thread-17] c.w.d.m.M.categoryRead : <== Updates: 361
Exception in thread "Thread-18" 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 involve defaultParameterMap
### The error occurred while setting parameters
### SQL: update msg_user_record set read_status = 1, read_time = now() where user_id = ? and msg_id = ? and read_status=0;
### Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
; SQL []; 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:263)
at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:73)
at org.mybatis.spring.MyBatisExceptionTranslator.translateExceptionIfPossible(MyBatisExceptionTranslator.java:73)
at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:446)
at com.sun.proxy.$Proxy72.update(Unknown Source)
at org.mybatis.spring.SqlSessionTemplate.update(SqlSessionTemplate.java:294)
at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:63)
at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:59)
at com.sun.proxy.$Proxy78.msgRead(Unknown Source)
at com.wudy.download.service.Impl.MsgServiceImpl.read(MsgServiceImpl.java:27)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:333)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99)
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:282)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213)
at com.sun.proxy.$Proxy79.read(Unknown Source)
at com.wudy.download.controller.TestController.lambda$newTask$1(TestController.java:41)
at java.lang.Thread.run(Thread.java:748)
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:425)
at com.mysql.jdbc.Util.getInstance(Util.java:408)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:952)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3978)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3914)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2530)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2683)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2495)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1903)
at com.mysql.jdbc.PreparedStatement.execute(PreparedStatement.java:1242)
at com.zaxxer.hikari.proxy.PreparedStatementProxy.execute(PreparedStatementProxy.java:44)
at com.zaxxer.hikari.proxy.PreparedStatementJavassistProxy.execute(PreparedStatementJavassistProxy.java)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.ibatis.logging.jdbc.PreparedStatementLogger.invoke(PreparedStatementLogger.java:59)
at com.sun.proxy.$Proxy95.execute(Unknown Source)
at org.apache.ibatis.executor.statement.PreparedStatementHandler.update(PreparedStatementHandler.java:46)
at org.apache.ibatis.executor.statement.RoutingStatementHandler.update(RoutingStatementHandler.java:74)
at org.apache.ibatis.executor.SimpleExecutor.doUpdate(SimpleExecutor.java:50)
at org.apache.ibatis.executor.BaseExecutor.update(BaseExecutor.java:117)
at org.apache.ibatis.executor.CachingExecutor.update(CachingExecutor.java:76)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.ibatis.plugin.Plugin.invoke(Plugin.java:63)
at com.sun.proxy.$Proxy93.update(Unknown Source)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.ibatis.plugin.Plugin.invoke(Plugin.java:63)
at com.sun.proxy.$Proxy93.update(Unknown Source)
at org.apache.ibatis.session.defaults.DefaultSqlSession.update(DefaultSqlSession.java:198)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:433)
... 21 more
排查过程
首先我们了解到既然是mysql的deadlock发生,那么我们查看下mysql的日志,在mysql中执行下面的命令:
show ENGINE INNODB STATUS;
提取日志:
------------------------
LATEST DETECTED DEADLOCK
------------------------
2020-09-25 12:01:32 0x700008464000
*** (1) TRANSACTION:
TRANSACTION 102628, ACTIVE 0 sec starting index read
mysql tables in use 3, locked 3
LOCK WAIT 4 lock struct(s), heap size 1136, 3 row lock(s)
MySQL thread id 626, OS thread handle 123145442246656, query id 9643 localhost 127.0.0.1 root updating
update msg_user_record
set read_status = 1,
read_time = now()
where user_id = '54504790680291242936083' and msg_id = 'M4805831019234066910' and read_status=0
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 3291 page no 46 n bits 544 index user_idx of table `test`.`msg_user_record` trx id 102628 lock_mode X waiting
Record lock, heap no 5 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 23; hex 3534353034373930363830323931323432393336303833; asc 54504790680291242936083;;
1: len 4; hex 0000668c; asc f ;;
*** (2) TRANSACTION:
TRANSACTION 102627, ACTIVE 0 sec fetching rows
mysql tables in use 3, locked 3
53 lock struct(s), heap size 8400, 4683 row lock(s)
MySQL thread id 625, OS thread handle 123145441132544, query id 9641 localhost 127.0.0.1 root updating
update msg_user_record
set read_status = 1,
read_time = now()
where user_id = '54504790680291242936083' and cat_code = 'cstmbus' and read_status=0
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 3291 page no 46 n bits 544 index user_idx of table `test`.`msg_user_record` trx id 102627 lock_mode X
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
0: len 8; hex 73757072656d756d; asc supremum;;
Record lock, heap no 5 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 23; hex 3534353034373930363830323931323432393336303833; asc 54504790680291242936083;;
1: len 4; hex 0000668c; asc f ;;
....................
....................
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 3291 page no 162 n bits 208 index PRIMARY of table `test`.`msg_user_record` trx id 102627 lock_mode X locks rec but not gap waiting
Record lock, heap no 94 PHYSICAL RECORD: n_fields 13; compact format; info bits 0
0: len 4; hex 0000b157; asc W;;
1: len 6; hex 000000019060; asc `;;
2: len 7; hex 5e000002b00490; asc ^ ;;
3: len 23; hex 3534353034373838373332373731363038353631343237; asc 54504788732771608561427;;
4: len 7; hex 6373746d627573; asc cstmbus;;
5: len 12; hex e699bae4baabe585ace4baa4; asc ;;
6: len 20; hex 4d34383035383331303139323334303636393130; asc M4805831019234066910;;
7: len 1; hex 00; asc ;;
8: len 5; hex 99a76f1704; asc o ;;
9: len 1; hex 00; asc ;;
10: len 5; hex 99a76f1704; asc o ;;
11: len 4; hex 5f6b14f3; asc _k ;;
12: len 4; hex 5f6d5f51; asc _m_Q;;
*** WE ROLL BACK TRANSACTION (1)
分析:从中我们可以看出事务1在等待获取锁(记录锁,也叫行锁) 0x0000668c;
事物2持有行锁(holds the lock)0x0000668c,等待获取行锁0x0000b157;
现在我们来了解下mysql的锁机制:
1.InnoDB通过索引来实现行锁，而不是通过锁住记录。因此，当操作的两条不同记录拥有相同的索引时，也会因为行锁被锁而发生等待。
2.由于InnoDB的索引机制，数据库操作使用了主键索引(primary)，InnoDB会锁住主键索引；使用非主键索引时，InnoDB会先锁住非主键索引(index)，再锁定主键索引。
我们再来看下两个事务的执行计划:
事务1:Using intersect(msg_id,user_idx); Using where
事务2: Using intersect(user_idx,cat_code); Using where
其中 using intersect就是mysql执行器优化后的执行计划,使用了索引合并(index merge)
现在我们再回头来分析下上面的mysql 死锁日志:
事务1由于索引合并的影响,先对索引msg_id加index锁,再对msg_id索引扫描结果record加primary锁成功,持有了record:0x0000b157(id=45399)的primary锁,此时开始获取user_idx索引锁.
事务2由于并发开始执行,也使用了索引合并,先成功获取了user_idx锁,也成功获取了含有1条
record:0x0000668c(id=26252)的primary锁,再去获取cat_code的index锁.
如下图
所以,形成了死锁(deadLock).最后根据权重计算,rollback了TRANSACTION(1)事务1
解决方式:
创建联合索引user_msg_index(user_id,msg_id)
总的来说,就是避免出现索引合并(using intersect)带来的复合锁影响.
更多对InnoDB锁的了解,请参考:
