MySQL Deadlock 复现步骤
建表SQL
CREATE TABLE `t_wms_order_item` (
`id` bigint(20) NOT NULL AUTO_INCREMENT,
`order_id` bigint(20) NOT NULL,
`u_t` bigint(20) DEFAULT NULL,
PRIMARY KEY (`id`),
KEY `idx_order` (`order_id`) USING BTREE
) ENGINE=InnoDB DEFAULT CHARSET=utf8;
-- 初始化语句
INSERT INTO `t_wms_order_item`(`id`, `order_id`, `u_t`) VALUES (1, 1, NULL);
INSERT INTO `t_wms_order_item`(`id`, `order_id`, `u_t`) VALUES (2, 1, NULL);
INSERT INTO `t_wms_order_item`(`id`, `order_id`, `u_t`) VALUES (3, 1, NULL);
INSERT INTO `t_wms_order_item`(`id`, `order_id`, `u_t`) VALUES (4, 2, NULL);
INSERT INTO `t_wms_order_item`(`id`, `order_id`, `u_t`) VALUES (5, 2, NULL);
INSERT INTO `t_wms_order_item`(`id`, `order_id`, `u_t`) VALUES (6, 2, NULL);
INSERT INTO `t_wms_order_item`(`id`, `order_id`, `u_t`) VALUES (7, 3, NULL);
INSERT INTO `t_wms_order_item`(`id`, `order_id`, `u_t`) VALUES (8, 3, NULL);
INSERT INTO `t_wms_order_item`(`id`, `order_id`, `u_t`) VALUES (9, 3, NULL);
INSERT INTO `t_wms_order_item`(`id`, `order_id`, `u_t`) VALUES (10, 2, NULL);
Java 代码
update
t_wms_order_item
set u_t = unix_timestamp()
where
order_id = #{orderId}
update
t_wms_order_item
set u_t = unix_timestamp()
where
id = #{id}
@Transactional
public int updateByOrderId(Long orderId) {
return mapper.updateByOrderId(orderId);
}
@Transactional
public int updateById(List idList) {
idList.forEach(id -> {
mapper.updateById(id);
// try {
Thread.sleep(1);
// } catch (InterruptedException e) {
// e.printStackTrace();
// }
});
return 1;
}
private static List list = new ArrayList() {{
add(10L);
add(6L);
add(5L);
add(4L);
}};
@Test
public void test() {
Thread thread1 = new Thread(() -> {
while (true) {
System.out.println("11111");
System.out.println("====" + orderItemManager);
orderItemManager.updateByOrderId(2L);
}
});
Thread thread2 = new Thread(() -> {
while (true) {
System.out.println(Thread.currentThread().getName() + "222222");
orderItemManager.updateById(list);
}
});
thread1.start();
thread2.start();
try {
thread2.join();
} catch (InterruptedException e) {
e.printStackTrace();
}
try {
thread1.join();
} catch (InterruptedException e) {
e.printStackTrace();
}
Exception in thread "Thread-2" 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 com.xxx.wms.mysql.mapper.OrderItemMapper.updateById-Inline
### The error occurred while setting parameters
### 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)
-05-15 14:21:34 DEBUG org.springframework.jdbc.datasource.DataSourceUtils doReleaseConnection:327 - Returning JDBC Connection to DataSource
11111
====com.xxx.wms.mysql.manager.OrderItemManager@4b013c76
-05-15 14:21:34 DEBUG org.springframework.jdbc.datasource.DataSourceTransactionManager getTransaction:367 - Creating new transaction with name [com.xxx.wms.mysql.manager.OrderItemManager.updateByOrderId]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT; ''
at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:371)
at com.sun.proxy.$Proxy14.update(Unknown Source)
at org.mybatis.spring.SqlSessionTemplate.update(SqlSessionTemplate.java:254)
at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:55)
at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:53)
at com.sun.proxy.$Proxy16.updateById(Unknown Source)
at com.xxx.wms.mysql.manager.OrderItemManager.lambda$updateById$0(OrderItemManager.java:36)
at java.util.ArrayList.forEach(ArrayList.java:1249)
at com.xxx.wms.mysql.manager.OrderItemManager.updateById(OrderItemManager.java:34)
at com.xxx.wms.mysql.manager.OrderItemManager$$FastClassBySpringCGLIB$$b1e58795.invoke()
at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:717)
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:281)
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.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:653)
at com.xxx.wms.mysql.manager.OrderItemManager$$EnhancerBySpringCGLIB$$7fa361d5.updateById()
at com.xxx.wms.mysql.manager.OrderItemManagerTest.lambda$test$1(OrderItemManagerTest.java:76)
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:404)
at com.mysql.jdbc.Util.getInstance(Util.java:387)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:948)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3870)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3806)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2470)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2617)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2550)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1861)
at com.mysql.jdbc.PreparedStatement.execute(PreparedStatement.java:1192)
-05-15 14:21:34 DEBUG org.springframework.jdbc.datasource.DataSourceTransactionManager doBegin:206 - Acquired Connection [jdbc:mysql://xxxxxxxxx:3306/yinzo?characterEncoding=utf8&allowMultiQueries=true&useAffectedRows=true, UserName=wms_dev@xxxxxxx, MySQL Connector Java] for JDBC transaction
at mons.dbcp.DelegatingPreparedStatement.execute(DelegatingPreparedStatement.java:172)
at mons.dbcp.DelegatingPreparedStatement.execute(DelegatingPreparedStatement.java:172)
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.$Proxy21.execute(Unknown Source)
at org.apache.ibatis.executor.statement.PreparedStatementHandler.update(PreparedStatementHandler.java:45)
at org.apache.ibatis.executor.statement.RoutingStatementHandler.update(RoutingStatementHandler.java:73)
at org.apache.ibatis.executor.ReuseExecutor.doUpdate(ReuseExecutor.java:51)
at org.apache.ibatis.executor.BaseExecutor.update(BaseExecutor.java:115)
at org.apache.ibatis.session.defaults.DefaultSqlSession.update(DefaultSqlSession.java:170)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
-05-15 14:21:34 DEBUG org.springframework.jdbc.datasource.DataSourceTransactionManager doBegin:223 - Switching JDBC Connection [jdbc:mysql://xxxxxx:3306/yinzo?characterEncoding=utf8&allowMultiQueries=true&useAffectedRows=true, UserName=wms_dev@xxx, MySQL Connector Java] to manual commit
at java.lang.reflect.Method.invoke(Method.java:498)
at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:358)
... 20 more
说明：死锁的条件是比较苛刻的，这里是使用两个线程执行，复现出来的次数依然不是很多。(执行过程中sleep一段时间好像有效果，但也不是很明显。)
MySQL死锁日志
------------------------
LATEST DETECTED DEADLOCK
------------------------
-05-15 14:21:18 7f5780e00700
*** (1) TRANSACTION:
TRANSACTION 6395717635, ACTIVE 0 sec fetching rows
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1184, 6 row lock(s), undo log entries 2
MySQL thread id 36275727, OS thread handle 0x7f57d0e92700, query id 5271067355 ****** wms_dev updating
update
t_wms_order_item
set u_t = unix_timestamp()
where
order_id = 2
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 145392 page no 3 n bits 104 index `PRIMARY` of table `yinzo`.`t_wms_order_item` trx table locks 1 total table locks 2 trx id 6395717635 lock_mode X waiting lock hold time 0 wait time before grant 0
*** (2) TRANSACTION:
TRANSACTION 6395717634, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
3 lock struct(s), heap size 1184, 3 row lock(s), undo log entries 2
MySQL thread id 36275728, OS thread handle 0x7f5780e00700, query id 5271067356 ****** wms_dev updating
update
t_wms_order_item
set u_t = unix_timestamp()
where
id = 5
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 145392 page no 3 n bits 104 index `PRIMARY` of table `yinzo`.`t_wms_order_item` trx table locks 1 total table locks 2 trx id 6395717634 lock_mode X locks rec but not gap lock hold time 0 wait time before grant 0
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 145392 page no 3 n bits 104 index `PRIMARY` of table `yinzo`.`t_wms_order_item` trx table locks 1 total table locks 2 trx id 6395717634 lock_mode X locks rec but not gap waiting lock hold time 0 wait time before grant 0
*** WE ROLL BACK TRANSACTION (2)
查询MySQL死锁日志命令：
-- 查看引擎信息(查看死锁日志)控制台执行
show engine innodb status;
-- 下面是详细的日志信息设置，可以自己配置
-- 查看死锁日志是否开启
show variables like "%innodb_print_all_deadlocks%";
set global slow_query_log = 1;
死锁日志基本信息
LOCK_REC_NOT_GAP (锁记录)
LOCK_GAP 锁记录前的GAP)
LOCK_ORDINARY(同时锁记录+记录前的GAP 。传说中的Next Key锁)
LOCK_INSERT_INTENTION(插入意向锁，其实是特殊的GAP锁)
锁的属性可以与锁模式任意组合。
例如：
lock->type_mode 可以是Lock_X 或者 Lock_S
locks gap before rec 表示为gap锁：lock->type_mode & LOCK_GAP
locks rec but not gap 表示为记录锁，非gap锁：lock->type_mode & LOCK_REC_NOT_GAP
insert intention 表示为插入意向锁：lock->type_mode & LOCK_INSERT_INTENTION
waiting 表示锁等待：lock->type_mode & LOCK_WAIT
日志分析：
1. 事务1，正在执行updatet_wms_order_item set u_t = unix_timestamp() where order_id = 2; 日志中 lock_mode X waiting 表示正在申请index `PRIMARY` 索引上的X锁。
2. 事务2，HOLDS THE LOCK(S): 事务2持有index `PRIMARY`索引上的X锁lock_mode X locks rec but not gap 并且是锁记录，即锁定了 id = 10，id = 6 两条记录。
3. 事务2，WAITING FOR THIS LOCK TO BE GRANTED：事务2正在申请index `PRIMARY`索引上的X锁 lock_mode X locks rec but not gap waiting。
4. 事务1 申请index `PRIMARY`索引上X锁的顺序，4 -> 5-> 6 -> 10， 事务2 的申请顺序，10-> 6-> 5-> 4。不同事务对同一个字段的锁的申请是需要排队的，形成了循环等待，最终看日志，WE ROLL BACK TRANSACTION (2) 回滚了事务2。
产生疑问1：事务1加的锁是有哪些？
事务隔离级别repeatable read -- 这个是前提
加锁规则：
加锁规则里面，包含了两个“原则”、两个“优化”和一个“bug”。
1. 原则1：加锁的基本单位是next-key lock。next-key lock是前开后闭区间。
2. 原则2：查找过程中访问到的对象才会加锁。
3. 优化1：索引上的等值查询，给唯一索引加锁的时候，next-key lock退化为行锁。
4. 优化2：索引上的等值查询，向右遍历时且最后一个值不满足等值条件的时候，next-key lock退化为间隙锁。
5. 一个bug：唯一索引上的范围查询会访问到不满足条件的第一个值为止。
事务2的加锁，同理。
MySQL加行锁是一行一行去lock。
后续考虑：
update 二级索引上操作加锁步骤
1. 获取idx_order 上的锁。
2. 获取主键索引上的行级锁。
3. 更新完毕后，提交释放所有锁。
极端情况，事务A获取了idx_order索引上的锁，等待主键索引上的锁；事务B获取了主键索引上的锁，等待idx_order的锁。
这个情况不太好验证。
