一、问题现象

线上接口在并发请求的场景部分请求失败,查询线上日志发现时出现死锁,异常日志如下:

org.apache.ibatis.exceptions.PersistenceException:
### Error querying database. Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
### The error may exist in com/....../dao/mapper/ShortLinkMapper.xml
### The error may involve defaultParameterMap
### The error occurred while setting parameters
### SQL: select * from short_link_id_map where table_name_index = ? and year = ? for update
### Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction

根据异常日志,是在执行select for update时产生了死锁,接下来分析一下死锁日志并结合业务逻辑分析出死锁的原因。

二、业务逻辑分析

该接口是一个短链生成接口,提供批量生成短链的能力,业务逻辑如下:

  • 1.客户端调用ID短链接口,批量生成短链
  • 2.接口从缓存队列中获取短链ID,如果队列为空则先批量获取1000个短链ID加入队列
  • 3.获取短链ID完成后,同步更新短链ID映射表

短链ID映射表:短链记录按天分表,根据短链ID映射表确认短链所在的分表
业务逻辑

数据库表结构

create table short_link_id_map
(
    year             int not null comment '年份',
    table_name_index varchar(10)      not null comment '短连接表名后缀,主键',
    start_id         bigint           null comment '开始ID',
    end_id           bigint           null comment '结束ID',
    primary key (year, table_name_index)
)
    comment '短连接ID映射表';

产生死锁的事务

-- 1.获取ID短链映射记录,只会有一条记录
select * from short_link_id_map
where table_name_index = #{tableNameIndex} and year = #{year}
for update;
-- 2.短链ID映射记录存在,则更新endId
update short_link_id_map set end_id = #{endId}
where table_name_index=${tableNameIndex} and year=#{year}
and end_id < #{endId}

产生死锁的事务如上,其中事务中的第一条语句使用了select for update,目的是为了解决多节点并发插入引起主键冲突。

事务执行场景

根据线上环境,事务执行的情况如下图所示:
事务执行示意图
在单节点下不会出现死锁,而多个节点并发的执行上面的事务,就会出现死锁的现象。
死锁日志

死锁分析

首先我们得了解MySQL中加锁的基本单位是邻键锁(行锁 + 间隙锁),如果遇到唯一索引,则邻键锁退化为行锁,详情请参阅MySQL官网
第一条SQL:select for update ,where条件使用了主键索引,所以在查询记录上加行锁。
第二条SQL:update, 由于where条件是会走主键索引,所以也是在要更新的记录上加行锁。
根据事务中的SQL操作,两条SQL会对同一个行记录加行锁,理论上是不会产生死锁的。从SQL中无法分析出产生死锁具体原因,所以需要查看MySQL的死锁日志。

三、死锁日志

使用SHOW ENGINE INNODB STATUS;命令查看最后一个死锁日志,内容如下:

=====================================
2023-03-07 12:58:29 0x7fe705b44700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 9 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 100159 srv_active, 0 srv_shutdown, 1185548 srv_idle
srv_master_thread log flush and writes: 1285611
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 209834
OS WAIT ARRAY INFO: signal count 212844
RW-shared spins 0, rounds 407264, OS waits 186247
RW-excl spins 0, rounds 316974, OS waits 7975
RW-sx spins 28, rounds 627, OS waits 12
Spin rounds per wait: 407264.00 RW-shared, 316974.00 RW-excl, 22.39 RW-sx
------------------------
LATEST DETECTED DEADLOCK
------------------------
2023-03-07 12:57:09 0x7fe72781c700
*** (1) TRANSACTION:
TRANSACTION 1686739378, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 1136, 1 row lock(s)
MySQL thread id 10768, OS thread handle 140630204196608, query id 4101047 172.16.124.217 root statistics
select *
        from short_link_id_map
        where table_name_index = '0303'
          and year = 2023
        for update
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
-- 事务1:等待一个行锁,这个行锁是添加到主键索引上的
RECORD LOCKS space id 25270 page no 3 n bits 160 index PRIMARY of table `db`.`short_link_id_map` trx id 1686739378 lock_mode X locks rec but not gap waiting
-- 事务1:等待的行锁对应的行内容如下:
Record lock, heap no 88 PHYSICAL RECORD: n_fields 6; compact format; info bits 0
 0: len 4; hex 800007e7; asc     ;;
 1: len 4; hex 30333033; asc 0303;;
 2: len 6; hex 000064899693; asc   d   ;;
 3: len 7; hex 6c000014e80d9a; asc l      ;;
 4: len 8; hex 8000000002e70503; asc         ;;
 5: len 8; hex 8000000002e70513; asc         ;;
 
*** (2) TRANSACTION:
TRANSACTION 1686739377, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
3 lock struct(s), heap size 1136, 2 row lock(s)
MySQL thread id 10760, OS thread handle 140630776989440, query id 4101048 172.16.124.217 root updating
update short_link_id_map
         SET end_id = 48694547
        where table_name_index=0303 and year=2023
          
            and end_id < 48694547
*** (2) HOLDS THE LOCK(S):
-- 事务2:持有一个行锁,这个行锁是添加到主键索引上的
RECORD LOCKS space id 25270 page no 3 n bits 160 index PRIMARY of table `db`.`short_link_id_map` trx id 1686739377 lock_mode X locks rec but not gap
-- 事务2:持有的行锁对应的行内容如下:
Record lock, heap no 88 PHYSICAL RECORD: n_fields 6; compact format; info bits 0
 0: len 4; hex 800007e7; asc     ;;
 1: len 4; hex 30333033; asc 0303;;
 2: len 6; hex 000064899693; asc   d   ;;
 3: len 7; hex 6c000014e80d9a; asc l      ;;
 4: len 8; hex 8000000002e70503; asc         ;;
 5: len 8; hex 8000000002e70513; asc         ;;
 
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
-- 事务2:等带一个邻键锁,这个行锁是添加到主键索引上的
RECORD LOCKS space id 25270 page no 3 n bits 160 index PRIMARY of table `db`.`short_link_id_map` trx id 1686739377 lock_mode X waiting
-- 事务2:等待的加锁的记录内容如下:
Record lock, heap no 88 PHYSICAL RECORD: n_fields 6; compact format; info bits 0
 0: len 4; hex 800007e7; asc     ;;
 1: len 4; hex 30333033; asc 0303;;
 2: len 6; hex 000064899693; asc   d   ;;
 3: len 7; hex 6c000014e80d9a; asc l      ;;
 4: len 8; hex 8000000002e70503; asc         ;;
 5: len 8; hex 8000000002e70513; asc         ;;
 
*** WE ROLL BACK TRANSACTION (1)

日志分析

根据以上异常日志,我们详细分析可以得出以下结论。

  • 事务1:等待行锁(lock_mode X locks rec but not gap waiting)
  • 事务2:持有行锁(lock_mode X locks rec but not gap)
  • 事务2:等待邻键锁(lock_mode X waiting)

根据事务推进顺序,事务2持有一个行锁,事务1等待事务2持有的行锁,事务2申请一个邻键锁,而且这个邻键锁等待事务2自己持有的行锁。从而触发死锁检测条件,最后回滚事务1,导致事务1对应的请求失败。

为什么会产生死锁?

从以上的死锁日志来看,发生死锁的两个事务,事务1只是在等待锁并没有持有锁,而事务2持有一个行锁,再次申请该行锁对应的邻键锁时触发了死锁检测,导致事务1回滚。
而根据我们的分析,此时并不存在锁竞争,为什么就死锁了呢?

不符合理论的现象

而且更为奇怪的是为什么第二条SQL执行update语句的SQL请求的是一个邻键锁,update语句明显是走了主键索引,主键索引则会将邻键锁退化为行锁,为什么在这个事务中邻键锁没有退化为行锁

死锁重现

在本地环境同时开启两个会话,按照上述事务推进顺序进行测试,并不会产生死锁。但是本地环境在进行并发测试的时候,则会频繁出现死锁。

死锁产生的场景

对于死锁检测的机制和我们对死锁的认知存在一定的区别,我在一个MySQL的一个bug清单中找到了MySQL团队给予的回复:

The very misleading part of the output is that the section is titled “HOLDS THE LOCK(S)”, while in fact not every lock mentioned in this section is actually “held”. It’s still in the process of acquisition, as evidenced by the word “waiting”.
The reason this lock is listed in the section titled “HOLDS THE LOCK(S)” is because for the purpose of deadlock detection algorithm, a request for an X-lock is treated very similarly to already holding an X-lock.
And this is done to correctly model the fact, that transactions which request S-lock, have to wait not only for transactions already holding an X-lock, but also for transactions which merely requested it, but still wait for it to be granted - this is done to avoid the problem of “starvation of writers by readers”.
Another reason (perhaps more important for your case) which is a bit similar, is that a transaction which requests an X-lock, has to wait for its turn, giving priority to transaction which already waits for an X-lock (in mysql 5.6 and 5.7 there’s simply a FIFO queue, and in 8.0 there is also CATS algorithm, but both algorithms try to ensure that new-coming transaction waits for those already in queue). This again is done to avoid starvation: this time among writers themselves.
So, given that InnoDB forces transactions to wait for a transaction which waits for an X-lock, it might mean that a deadlock is possible, in which one of the edges in the deadlock cycle involves waiting for transaction which still waits for an X-lock.
And the simplest way to model it in the deadlock checking algorithm is to treat the “X-lock being waited for” as “already held”.

输出中非常具有误导性的部分是该部分标题为“HOLDS THE LOCK(S)”,而实际上并非本节中提到的每个锁实际上都“持有”。 还在请求过程中,“待”字就是明证。
这个锁被列在标题为“HOLDS THE LOCK(S)”的部分中的原因是出于死锁检测算法的目的,对 X 锁的请求与已经持有 X 锁的处理方式非常相似。
这样做是为了正确地模拟这样一个事实,即请求 S 锁的事务不仅要等待已经持有 X 锁的事务,还要等待仅请求它但仍在等待它被授予的事务—— 这样做是为了避免“读请求饿死写请求”的问题。
另一个有点相似的原因(对于您的情况可能更重要)是请求 X 锁的事务必须等待轮到它,优先考虑已经等待 X 锁的事务(在 mysql 5.6 中 5.7 有一个简单的 FIFO 队列,8.0 也有 CATS 算法,但两种算法都试图确保新到来的事务等待已经在队列中的事务)。 这样做也是为了避免饥饿:这次是在写请求自己中间。
因此,鉴于 InnoDB 强制事务等待 X 锁的事务,这可能意味着死锁是可能的,其中死锁周期中的一个边缘涉及等待仍在等待 X- 的事务锁。
在死锁检查算法中对其建模的最简单方法是将“正在等待的 X 锁”视为“已持有”。

文章见:Weird deadlock behavior where a transaction holds a lock on an index, and the SAME transactions also waits for a lock on the exact SAME index

总结来说就是MySQL死锁检测算法按照相似方式处理请求X锁的事务持有X锁的事务,因为多个事务请求X锁时需要进行排队,而X锁释放后会按照队列中的顺序去获得锁。
根据以上结论,死锁产生的原因为:事务2持有行锁,事务1请求行锁,事务2请求邻键锁需要在事务1后排队行程环路,从而触发了死锁检测,示意图如下:
死锁示意图

仍存在的两个疑问?

通过上述的解释,我们明白了死锁产生的场景,但是有两个问题仍然存在疑问:

  • 为什么事务2在持有行锁的情况下,再请求一个邻键锁(行锁与间隙锁的组合)时被检测为死锁呢?
  • 为什么在执行第二条update时明显走了主键索引,但请求的是邻键锁而不是行锁?

四、MySQL的一个BUG

通过查看MySLQ加锁的源码解析,发现MySQL存在的一个bug,详情参见以下文章:
InnoDB 死锁 Bug 排查
Bug #82127 Deadlock with 3 concurrent DELETEs by UNIQUE key

简而言之

官方在 8.0.18 版本对死锁检测进行了优化, 将原先的死锁检测机制交给了background thread 来处理, 具体的Patch链接:MySQL-8.0.18 死锁检测优化. 具体的思路是将当前事务系统的 lock 信息打一份快照, 由这份快照判断是否存在回环, 假如存在死锁即唤醒等待事务.
而在 8.0.17 版本依然采用旧的死锁检测方法,每次申请lock失败进入wait状态后触发一下死锁检测,由于存在锁等待的环路,所以被检测为死锁。
用一句话来说就是MySQL 8.0.18之前不支持行锁升级到邻键锁,所以在持有行锁的情况下,基于此行锁升级至邻键锁时,由于存在等待环路,而被检测为死锁。

五、邻键锁为什么没有退化为行锁

通过上述MySQL的bug分析,我们了解到MySQL不支持锁升级导致了死锁的产生。
但是目前还存在一个问题,事务中第二条更新语句使用到主键索引,通过执行计划看也是会走主键索引,为什么这里的邻键锁没有退化为行锁呢?

update short_link_id_map set end_id = #{endId}
where table_name_index=${tableNameIndex} and year=#{year}
and end_id < #{endId}

猜想与验证

因为这个表的记录并不多,总共不超过1000行,而MySQL的查询基于成本优化,是不是在成本优化后,没有选择走主键索引,二是走了全表扫描呢?
我们更新条件中除了有主见索引外,还有一个普通列,是否查询条件会影响MySQL的执行计划,我们将update修改为select通过执行计划验证一下:
全表扫描验证
根据以上验证结果,我们可以发现,当我们修改where条件中的主键索引后面的条件时,执行计划显示会存在走全表扫描的情况。

结论

更新操作虽然使用了主键索引,但是同时存在一个普通的where条件,而且由于表内容较少,在并发请求时有一定的概率走全表扫描,而全表扫描则会加邻键锁。

六、解决方案

根据业务场景,我们使用select for update主要时为了解决并发插入主键冲突的问题,但是实际业务中一天只会进行一次插入,其余的都是更新操作。所以我们直接去除了select中的for update,减小了事务,对于并发插入问题,使用insert ... on duplicate key update解决并发插入的问题。

注意事项

insert ... on duplicate key update在并发情况下也会产生死锁,但是实际业务中并存在这种场景。具体原因这里不做展开,有兴趣的同学可以自己探索一下,死锁日志如下;

=====================================
2023-03-07 16:01:08 0x7fe705b44700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 46 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 100781 srv_active, 0 srv_shutdown, 1195883 srv_idle
srv_master_thread log flush and writes: 1296568
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 211624
OS WAIT ARRAY INFO: signal count 214692
RW-shared spins 0, rounds 410284, OS waits 187670
RW-excl spins 0, rounds 326082, OS waits 8247
RW-sx spins 29, rounds 657, OS waits 12
Spin rounds per wait: 410284.00 RW-shared, 326082.00 RW-excl, 22.66 RW-sx
------------------------
LATEST DETECTED DEADLOCK
------------------------
2023-03-07 15:51:02 0x7fe705556700
*** (1) TRANSACTION:
TRANSACTION 1686742571, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 4 lock struct(s), heap size 1136, 2 row lock(s)
MySQL thread id 10937, OS thread handle 140630203115264, query id 4160546 172.16.124.217 root update
insert into short_link_id_map (year, table_name_index, start_id, end_id)
        values (2023, '0304', 48694560,
                48694570)
        on duplicate key update end_id = if(end_id  < 48694570, 48694570, end_id)
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 25270 page no 3 n bits 160 index PRIMARY of table `cmp_gsms_2.0`.`gsms_short_link_id_map` trx id 1686742571 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 89 PHYSICAL RECORD: n_fields 6; compact format; info bits 0
 0: len 4; hex 80000833; asc    3;;
 1: len 4; hex 31323331; asc 1231;;
 2: len 6; hex 0000648995f6; asc   d   ;;
 3: len 7; hex 6f000014de10a9; asc o      ;;
 4: len 8; hex 8000000000000004; asc         ;;
 5: len 8; hex 8000000000001130; asc        0;;
 
*** (2) TRANSACTION:
TRANSACTION 1686742572, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
4 lock struct(s), heap size 1136, 2 row lock(s)
MySQL thread id 10938, OS thread handle 140630203655936, query id 4160547 172.16.124.217 root update
insert into gsms_short_link_id_map (year, table_name_index, start_id, end_id)
        values (2023, '0304', 48694560,
                48694570)
        on duplicate key update end_id = if(end_id  < 48694570, 48694570, end_id)
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 25270 page no 3 n bits 160 index PRIMARY of table `cmp_gsms_2.0`.`gsms_short_link_id_map` trx id 1686742572 lock_mode X locks gap before rec
Record lock, heap no 89 PHYSICAL RECORD: n_fields 6; compact format; info bits 0
 0: len 4; hex 80000833; asc    3;;
 1: len 4; hex 31323331; asc 1231;;
 2: len 6; hex 0000648995f6; asc   d   ;;
 3: len 7; hex 6f000014de10a9; asc o      ;;
 4: len 8; hex 8000000000000004; asc         ;;
 5: len 8; hex 8000000000001130; asc        0;;
 
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 25270 page no 3 n bits 160 index PRIMARY of table `cmp_gsms_2.0`.`gsms_short_link_id_map` trx id 1686742572 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 89 PHYSICAL RECORD: n_fields 6; compact format; info bits 0
 0: len 4; hex 80000833; asc    3;;
 1: len 4; hex 31323331; asc 1231;;
 2: len 6; hex 0000648995f6; asc   d   ;;
 3: len 7; hex 6f000014de10a9; asc o      ;;
 4: len 8; hex 8000000000000004; asc         ;;
 5: len 8; hex 8000000000001130; asc        0;;
 
*** WE ROLL BACK TRANSACTION (2)

七、总结

  • MySQL的死锁检测算法中,虽然一个事务在请求X锁而并不持有X锁,仍会触发死锁检测,原因由于请求X锁会进行排队;
  • MySQL 8.0.18 版本之前不支持行锁升级至邻键锁或更严格的锁,这与MySQL的死锁键锁实现机制相关;
  • update操作的where条件中存在主键索引与普通列,在并发场景下,存在一定概率走全表扫描,而至于为什么会走全表,则需要探索MySQL的成本优化机制。

参考文章

https://keithlan.github.io/2017/06/05/innodb_locks_1/
https://dev.mysql.com/doc/refman/5.7/en/innodb-locking.html
https://dev.mysql.com/doc/refman/8.0/en/innodb-locks-set.html
https://leviathan.vip/2021/02/25/mysql-deadlock-bugfix-23755664/
https://bugs.mysql.com/bug.php?id=82127