线上死锁分析解决纪实

技术
,

服务发生死锁，死锁检测时间较长，31s后死锁检测出来事务才得以回滚，期间不断有相同请求进来，造成死锁越来越复杂，并且服务端线程池中的所有线程都在等待锁，最后造成服务端线程池无空闲线程，拒绝服务。

注意：单条 SQL 也是一个事务，也会和其他事务发生死锁。

原因分析

首先奉上 InnoDB 日志 和 DDL

1
2
3
4
5
6
7
8
CREATE TABLE `campaignmockqueue` (
  `id` int(10) unsigned NOT NULL AUTO_INCREMENT,
  `campaignid` int(10) unsigned NOT NULL,
  `addtime` int(10) unsigned NOT NULL,
  PRIMARY KEY (`id`),
  KEY `idx_campid` (`campaignid`),
  KEY `addtime` (`addtime`)
) ENGINE=InnoDB AUTO_INCREMENT=1065620134 DEFAULT CHARSET=utf8
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
------------------------
LATEST DETECTED DEADLOCK
------------------------
2019-05-16 15:38:17 0x7f121830f700
*** (1) TRANSACTION:
TRANSACTION 161027737922, ACTIVE 0 sec fetching rows
mysql tables in use 1, locked 1
LOCK WAIT 88 lock struct(s), heap size 24784, 1412 row lock(s), undo log entries 2
MySQL thread id 42610991, OS thread handle 139701841643264, query id 40446554160 10.7.23.224 promotio_e0a1 updating
/*id:6d7cc9a7*/DELETE FROM `campaignmockqueue` WHERE `campaignid`=52327710 and `addtime` <= 1557992297
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 1975 page no 5280 n bits 1272 index idx_campid of table `promotion`.`campaignmockqueue` trx id 161027737922 lock_mode X waiting
*** (2) TRANSACTION:
TRANSACTION 161027729748, ACTIVE 31 sec inserting
mysql tables in use 1, locked 1
7 lock struct(s), heap size 1136, 7 row lock(s), undo log entries 14
MySQL thread id 42610752, OS thread handle 139715692001024, query id 40446554260 10.43.174.209 promotio_e0a1 update
/*id:dfdc4b66*/INSERT INTO `campaignmockqueue`(
           `campaignid`, `addtime`
        )
        VALUES
          
            (52327709, 1557992297)
         , 
            (52327709, 1559383140)
         , 
            (52327709, 1557992296)
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 1975 page no 5280 n bits 1272 index idx_campid of table `promotion`.`campaignmockqueue` trx id 161027729748 lock_mode X locks rec but not gap
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 1975 page no 5271 n bits 1272 index idx_campid of table `promotion`.`campaignmockqueue` trx id 161027729748 lock_mode X locks gap before rec insert intention waiting
*** WE ROLL BACK TRANSACTION (2)

如果看不懂日志，可以参考 这个文章

我们先来看看 事务1 和事务2 分别持有什么锁，又在等待什么锁。由于日志是在事务 1 的角度来打印的，所以我们只能看到事务 2 持有 lock_mode X locks rec but not gap 锁，在等待 lock_mode X locks gap before rec insert intention 锁。

lock_mode X locks rec but not gap 就是写记录锁，只锁了单条记录。

lock_mode X locks gap before rec insert intention 就是一个插入意向锁，目标是在对应的间隙上（不包括记录本身）加锁。

通过事务 2 的锁信息我们可以推测出事务 1 的锁持有信息，因此就有了下面的图。

事务 1 当前拥有的应该是间隙 A 和 记录X 组成的 nexy-key 锁 ，现在正在等待的是间隙 b 的锁。

1
DELETE FROM `campaignmockqueue` WHERE `campaignid`=52327710 and `addtime` <= 1557992297

事务 2 当前拥有的应该是 记录 Y 的 X锁， 间隙 D 的插入意向锁， 间隙 C 的插入意向锁 ，现在正在等待的是间隙 e 的 间隙插入意向锁（也有可能是 记录 Y 的 record lock）。

1
INSERT INTO `campaignmockqueue`(`campaignid`, `addtime` )VALUES (52327709, 1557992297) , (52327709, 1559383140), (52327709, 1557992296)

由于 next-key 锁 和 插入意向锁互斥，所以事务 1 在等待事务 2 释放 C, Y, D；事务 2 在等待事务 1 释放 A。 这样看来正好符合 InnoDB 中的 log。

模拟流程

个人认为 由于 next-key 锁和 Gap 锁不是一种锁，因此必然存在时间差，这种时间差在并发量很大的情况下才会凸显出来。

事务1 事务2
INSERT INTO campaignmockqueue 记录 Y
DELETE FROM campaignmockqueue 获取了 A 的间隙锁还没获取 next-key 锁
INSERT INTO campaignmockqueue(campaignid, addtime )VALUES (52327709, 1557992297) , (52327709, 1559383140), (52327709, 1557992296) （阻塞）
DELETE FROM campaignmockqueue 获取 next-key 锁 （阻塞）

验证猜想

上面的情况仅仅是推测，如果我们能拿到 INSERT 语句角度的死锁日志就好了。搜寻了一下 InnoDB 日志，得到了下面的日志，通过交叉分析，可以验证了我们的猜想。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
------------------------
LATEST DETECTED DEADLOCK
------------------------
2019-05-16 03:02:36 0x7f11eebd8700
*** (1) TRANSACTION:
TRANSACTION 161022641521, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 5 lock struct(s), heap size 1136, 3 row lock(s), undo log entries 2
MySQL thread id 42518313, OS thread handle 139715027216128, query id 40270385508 10.7.224.35 promotio_e0a1 update
/*id:dfdc4b66*/INSERT INTO `campaignmockqueue`(
`campaignid`, `addtime`
)
VALUES

(52247612, 1557946956)
, 
(52247612, 1557936000)
, 
(52247612, 1558022399)
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 1975 page no 4904 n bits 1264 index addtime of table `promotion`.`campaignmockqueue` trx id 161022641521 lock_mode X locks gap before rec insert intention waiting
*** (2) TRANSACTION:
TRANSACTION 161022641523, ACTIVE 0 sec fetching rows
mysql tables in use 1, locked 1
4 lock struct(s), heap size 1136, 3 row lock(s), undo log entries 1
MySQL thread id 42543917, OS thread handle 139714996569856, query id 40270385509 10.7.23.224 promotio_e0a1 updating
/*id:6d7cc9a7*/DELETE FROM `campaignmockqueue` WHERE `campaignid`=52247612 and `addtime` <= 1557946956
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 1975 page no 4904 n bits 1264 index addtime of table `promotion`.`campaignmockqueue` trx id 161022641523 lock_mode X
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 1975 page no 4904 n bits 1264 index addtime of table `promotion`.`campaignmockqueue` trx id 161022641523 lock_mode X waiting
*** WE ROLL BACK TRANSACTION (2)

解决方案

DELETE FROM campaignmockqueue 不使用 idx_campid 这个索引加锁，而使用唯一主键来做操作，和 insert 操作使用不同的索引，来避免这个问题。

参考文档

  1. 何登成的技术博客 » MySQL 加锁处理分析
  2. mysql并发insert死锁问题——gap、插入意向锁冲突 - hebaodan的博客 - OSCHINA
  3. MySQL 中的锁 [ 黄小豆的博客 ]
  4. 读 MySQL 源码再看 INSERT 加锁流程 - aneasystone’s blog
  5. Innodb死锁日志分段解读-如何阅读死锁日志 - 奎因&华洛 - CSDN博客
  6. MySQL DELETE 删除语句加锁分析 | | For DBA