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)

2020-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

2020-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)

2020-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 org.apache.commons.dbcp.DelegatingPreparedStatement.execute(DelegatingPreparedStatement.java:172)

at org.apache.commons.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)

2020-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

------------------------

2020-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，正在执行 update t_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的锁。

这个情况不太好验证。