记录一次死锁分析-Deadlock found when trying to get lock; try restarting transaction

场景描述

Laravel 中使用 MySQL 作为队列驱动时出现的。

版本：

MySQL 5.×
Laravel 5.×

stackoverflow 上相关的问题
Laravel Queue deadlock when deleting from jobs table [duplicate]

GitHub 相关的 issue
Laravel 5. PDOException. QUEUE_DRIVER=database 1213 Deadlock

报错信息

截图：

死锁截图_01

1 2	`(2/3) PDOException SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction`

分析前复习

InnoDB 的锁相关基础知识

InnoDB 实现了两种标准的行级锁

S Lock，允许事务读一行数据。
X Lock，允许事务删除或更新一行数据。

other

一致性的非锁定读（consistent nonlocking read）是 InnoDB 通过行多版本控制（multi versioning）的方式来读取当前执行时间数据库中行的数据。

如果读取的行正在执行 DELETE 或 UPDATE 操作，这时读取操作不会因此去等待行上锁的释放。相反的，InnoDB 引擎会去读取行的一个快照数据。

但是在某些情况下，用户需要显示地对数据库读取操作进行加锁以保证数据逻辑地一致性。而这需要数据库支持加锁语句，即使是对于 SELECT 的只读操作。

InnoDB 对于 SELECT 语句支持两种一致性的锁定读（locking read）操作：

1 2	`SELECT...FOR UPDATE -- 加 X 锁 SELECT...LOCK IN SHARE MODE -- 加 S 锁`

行锁三个的算法

Record Lock
Gap Lock
Next-Key Lock

死锁概念

两个或两个以上的事务在执行的过程中，因争夺锁的资源而造成的一种互相等待的现象。

思索底层原理-设计算法，没有看
数据库普遍采用 wait-for graph（等待图）的方式来进行死锁的检测，InnoDB 存储引擎也采用这种方式。通常使用深度优先的算法实现（新版本的使用非递归的方式）。

死锁Status

执行 show engine innodb status; 查看：

------------------------
LATEST DETECTED DEADLOCK
------------------------
2021-07-29 01:46:39 0x75740
*** (1) TRANSACTION:
TRANSACTION 245747603, ACTIVE 0 sec fetching rows
mysql tables in use 1, locked 1
LOCK WAIT 280 lock struct(s), heap size 24784, 2711 row lock(s)
MySQL thread id 25494, OS thread handle 481092, query id 9164199 40.72.155.168 adminedp Sending data
select * from `jobs` where `queue` = 'default' and ((`reserved_at` is null and `available_at` <= 1627523126) or (`reserved_at` <= 1627523036)) order by `id` asc limit 1 for update
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 2517233 n bits 80 index PRIMARY of table `j_mrplus`.`jobs` trx id 245747603 lock_mode X locks rec but not gap waiting
Record lock, heap no 8 PHYSICAL RECORD: n_fields 9; compact format; info bits 32
 0: len 8; hex 0000000000000c6f; asc        o;;
 1: len 6; hex 00000ea5cf92; asc       ;;
 2: len 7; hex 51001ec004105a; asc Q     Z;;
 3: len 7; hex 64656661756c74; asc default;;
 4: len 30; hex 7b22646973706c61794e616d65223a224170705c5c4a6f62735c5c507573; asc {"displayName":"App\\Jobs\\Pus; (total 2138 bytes);
 5: len 1; hex 01; asc  ;;
 6: len 4; hex 61020835; asc a  5;;
 7: len 4; hex 6102081c; asc a   ;;
 8: len 4; hex 61012c49; asc a ,I;;

*** (2) TRANSACTION:
TRANSACTION 245747602, ACTIVE 0 sec updating or deleting
mysql tables in use 1, locked 1
3 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 1
MySQL thread id 25491, OS thread handle 481088, query id 9164200 40.72.155.168 adminedp updating
delete from `jobs` where `id` = 3183
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 0 page no 2517233 n bits 80 index PRIMARY of table `j_mrplus`.`jobs` trx id 245747602 lock_mode X locks rec but not gap
Record lock, heap no 8 PHYSICAL RECORD: n_fields 9; compact format; info bits 32
 0: len 8; hex 0000000000000c6f; asc        o;;
 1: len 6; hex 00000ea5cf92; asc       ;;
 2: len 7; hex 51001ec004105a; asc Q     Z;;
 3: len 7; hex 64656661756c74; asc default;;
 4: len 30; hex 7b22646973706c61794e616d65223a224170705c5c4a6f62735c5c507573; asc {"displayName":"App\\Jobs\\Pus; (total 2138 bytes);
 5: len 1; hex 01; asc  ;;
 6: len 4; hex 61020835; asc a  5;;
 7: len 4; hex 6102081c; asc a   ;;
 8: len 4; hex 61012c49; asc a ,I;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 540697 n bits 824 index jobs_queue_index of table `j_mrplus`.`jobs` trx id 245747602 lock_mode X locks rec but not gap waiting
Record lock, heap no 518 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 7; hex 64656661756c74; asc default;;
 1: len 8; hex 0000000000000c6f; asc        o;;

*** WE ROLL BACK TRANSACTION (2)
------------
TRANSACTIONS
------------
Trx id counter 245749632
Purge done for trx's n:o < 245749567 undo n:o < 0 state: running but idle
History list length 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 281584660399920, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281584660413000, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281584660406024, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281584660412128, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281584660411256, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281584660402536, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281584660403408, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281584660401664, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281584660400792, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
--------

表结构

CREATE TABLE `jobs` (
  `id` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
  `queue` varchar(255) NOT NULL,
  `payload` longtext NOT NULL,
  `attempts` tinyint(3) unsigned NOT NULL,
  `reserved_at` int(10) unsigned DEFAULT NULL,
  `available_at` int(10) unsigned NOT NULL,
  `created_at` int(10) unsigned NOT NULL,
  PRIMARY KEY (`id`) USING BTREE,
  KEY `jobs_queue_index` (`queue`) USING BTREE
) ENGINE=InnoDB AUTO_INCREMENT=4306 DEFAULT CHARSET=utf8mb4;

表结构中，主键索引：id，辅助索引：queue。

死锁信息分析

事务 245747603 状态：

LOCK WAIT 280 lock struct(s)
2711 row lock(s)

thread id 25494
sql:

select 
    * 
from `jobs` 
where 
    `queue` = 'default' 
    and (
            (`reserved_at` is null and `available_at` <= 1627523126) or (`reserved_at` <= 1627523036)
        ) 
order by `id` asc 
limit 1 
for update

1
2
3

-- 表示锁住的资源， waiting：等待加 Record Lock（试图锁定一行记录）
-- locks rec but not gap 表示锁住的是一个索引而不是范围
RECORD LOCKS space id 0 page no 2517233 n bits 80 index PRIMARY of table `j_mrplus`.`jobs` trx id 245747603 lock_mode X locks rec but not gap waiting

事务 245747602 状态：

3 lock struct(s)
2 row lock(s)
thread id 25491

sql：

1	delete from `jobs` where `id` = 3183

1
2
3

-- 表示锁住的资源
-- locks rec but not gap 表示锁住的是一个索引而不是范围
RECORD LOCKS space id 0 page no 2517233 n bits 80 index PRIMARY of table `j_mrplus`.`jobs` trx id 245747602 lock_mode X locks rec but not gap

等待的锁：

1	RECORD LOCKS space id 0 page no 540697 n bits 824 index jobs_queue_index of table `j_mrplus`.`jobs` trx id 245747602 lock_mode X locks rec but not gap waiting

分析-重点

死锁出现在队列的消费执行中，相关的查询和删除的重要 sql 分别如下：

/**
 * Pop the next job off of the queue.
 *
 * @param  string  $queue
 * @return \Illuminate\Contracts\Queue\Job|null
 * @throws \Exception|\Throwable
 */
public function pop($queue = null)
{
    $queue = $this->getQueue($queue);

    try {
        $this->database->beginTransaction();

        if ($job = $this->getNextAvailableJob($queue)) {
            return $this->marshalJob($queue, $job);
        }

        $this->database->commit();
    } catch (Throwable $e) {
        $this->database->rollBack();

        throw $e;
    }
}

    /**
 * Get the next available job for the queue.
 *
 * @param  string|null  $queue
 * @return \Illuminate\Queue\Jobs\DatabaseJobRecord|null
 */
protected function getNextAvailableJob($queue)
{
    $job = $this->database->table($this->table)
                ->lockForUpdate()
                ->where('queue', $this->getQueue($queue))
                ->where(function ($query) {
                    $this->isAvailable($query);
                    $this->isReservedButExpired($query);
                })
                ->orderBy('id', 'asc')
                ->first();

    return $job ? new DatabaseJobRecord((object) $job) : null;
}

从下面的代码可知，删除前也会进行 X 锁查询：

/**
 * Delete a reserved job from the queue.
 *
 * @param  string  $queue
 * @param  string  $id
 * @return void
 * @throws \Exception|\Throwable
 */
public function deleteReserved($queue, $id)
{
    $this->database->transaction(function () use ($id) {
        if ($this->database->table($this->table)->lockForUpdate()->find($id)) {
            $this->database->table($this->table)->where('id', $id)->delete();
        }
    });
}

事务 245747603 的查询条件中有辅助索引 jobs_queue_index，列 queue，（下面的分析没有直接在日志里体现，经由代码分析）所以，这个事务InnoDB 会给使用 Next-Key Lock，不仅锁定范围，还会锁定记录本身，查询的排序是升序，所以每次新的查询都会类似锁定 （0, 3184] 这些记录

事务 245747602，查询的列为，主键索引（唯一索引），应用的锁算法为 Record Lock，只锁定了 id = 3183 的记录，由 InnoDB 实现的两种锁得知，加的行级锁为 X 锁。

结论

两个事务之间形成了 AB-BA 死锁。
即 A 在等待 B，B 在等待 A。

两个事务中不仅仅各有一条 sql，除了日志里体现的，由队列逻辑代码分析，其实还有其它的 sql

过程大概如下

队列系统正循环查询数据库中的记录进行消费和删除

队列逻辑：前一个事务 A，查到了 id=3183 进行了消费

消费完后进行删除，开启事务 245747602 (delete from jobs where id = 3183，删除操作也会尝试加 X 锁)，在这个删除操作前，还有一个尝试加 X 锁的查询，但是队列的下一次查询也开始进行了，查询条件中包含了辅助索引，所以事务要进行 Next-Key Lock，也就是类似范围为 （0, 3184） 的加锁，进入等待

两个事务的资源在相互等待，导致了报错 1213 的报错。

事务重新执行

事务的重新执行是 Laravel 处理的，没有影响业务。

处理办法

避免使用 MySQL 作为队列的驱动，尽量使用 Redis。

#laradock #php #mysql

记录一次死锁分析-Deadlock found when trying to get lock; try restarting transaction

https://hutaoren.cn/2020/07/29/记录一次死锁分析/

作者

胡桃仁

发布于

2020年7月29日

许可协议

Laravel 中的 IoC Container 上一篇

laradock+win10 构造多版本php 环境下一篇