线上死锁分析解决纪实

栏目: 数据库 · 发布时间: 5年前

内容简介：服务发生死锁，死锁检测时间较长，31s后死锁检测出来事务才得以回滚，期间不断有相同请求进来，造成死锁越来越复杂，并且服务端线程池中的所有线程都在等待锁，最后造成服务端线程池无空闲线程，拒绝服务。首先奉上 InnoDB 日志如果看不懂日志，可以参考

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

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

原因分析

首先奉上 InnoDB 日志

------------------------
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 的锁。

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

线上死锁分析解决纪实

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

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 日志，得到了下面的日志，通过交叉分析，可以验证了我们的猜想。

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