MySQL 死锁日志详解

内容分享11小时前发布

0 0 0

作者：操盛春，爱可生技术专家，公众号『一树一溪』作者，专注于研究 MySQL 和 OceanBase 源码。

爱可生开源社区出品，原创内容未经授权不得随意使用，转载请联系小编并注明来源。

本文基于 MySQL 8.0.32 源码，存储引擎为 InnoDB。

MySQL 死锁日志详解

正文

1. 准备工作

创建测试表：

CREATE TABLE `t1` (
  `id` int unsigned NOT NULL AUTO_INCREMENT,
  `i1` int DEFAULT '0',
  PRIMARY KEY (`id`) USING BTREE,
  KEY `idx_i1` (`i1`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb3;

插入测试数据：

INSERT INTO `t1` (`id`, `i1`) VALUES
(10, 101), (20, 201), (30, 301), (40, 401);

修改两个系统变量：

-- 每次出现死锁，都写入日志到 MySQL 错误日志文件
SET GLOBAL innodb_print_all_deadlocks = ON;

-- 写入死锁辅助信息
SET GLOBAL log_error_verbosity = 3;

2. 死锁日志

创建 2 个连接，按以下顺序执行示例 SQL：

-- 连接 1（事务 1）
BEGIN;
SELECT id FROM t1 WHERE id = 10 FOR UPDATE;

-- 连接 2（事务 2）
BEGIN;
SELECT id FROM t1 WHERE id = 20 FOR UPDATE;

-- 连接 1（事务 1）
SELECT i1 FROM t1 WHERE id = 20 FOR UPDATE;

-- 连接 2（事务 2）
SELECT * FROM t1 WHERE id = 10 FOR UPDATE;

示例 SQL 会导致死锁，MySQL 错误日志中会记录以下死锁日志：

2024-08-04T07:51:55.786277Z 0 [Note] [MY-012468] [InnoDB] Transactions deadlock detected, dumping detailed information.
2024-08-04T07:51:55.786346Z 0 [Note] [MY-012469] [InnoDB]  *** (1) TRANSACTION:
TRANSACTION 246047, ACTIVE 7 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1192, 2 row lock(s)
MySQL thread id 8, OS thread handle 123145473822720, query id 136 localhost 127.0.0.1 root statistics
SELECT i1 FROM t1 WHERE id = 20 FOR UPDATE
2024-08-04T07:51:55.786433Z 0 [Note] [MY-012469] [InnoDB]  *** (1) HOLDS THE LOCK(S):
RECORD LOCKS space id 0 page no 46 n bits 72 index PRIMARY of table `test`.`t1` trx id 246047 lock_mode X locks rec but not gap
Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 4; hex 0000000a; asc     ;;
 1: len 6; hex 00000003bf87; asc       ;;
 2: len 7; hex 81000001890110; asc        ;;
 3: len 4; hex 80000065; asc    e;;

2024-08-04T07:51:55.786800Z 0 [Note] [MY-012469] [InnoDB]  *** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 46 n bits 72 index PRIMARY of table `test`.`t1` trx id 246047 lock_mode X locks rec but not gap waiting
Record lock, heap no 3 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 4; hex 00000014; asc     ;;
 1: len 6; hex 00000003bf87; asc       ;;
 2: len 7; hex 8100000189011d; asc        ;;
 3: len 4; hex 800000c9; asc     ;;

2024-08-04T07:51:55.787156Z 0 [Note] [MY-012469] [InnoDB]  *** (2) TRANSACTION:
TRANSACTION 246048, ACTIVE 5 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1192, 2 row lock(s)
MySQL thread id 11, OS thread handle 123145474887680, query id 137 localhost 127.0.0.1 root statistics
SELECT * FROM t1 WHERE id = 10 FOR UPDATE
2024-08-04T07:51:55.787237Z 0 [Note] [MY-012469] [InnoDB]  *** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 0 page no 46 n bits 72 index PRIMARY of table `test`.`t1` trx id 246048 lock_mode X locks rec but not gap
Record lock, heap no 3 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 4; hex 00000014; asc     ;;
 1: len 6; hex 00000003bf87; asc       ;;
 2: len 7; hex 8100000189011d; asc        ;;
 3: len 4; hex 800000c9; asc     ;;

2024-08-04T07:51:55.787586Z 0 [Note] [MY-012469] [InnoDB]  *** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 46 n bits 72 index PRIMARY of table `test`.`t1` trx id 246048 lock_mode X locks rec but not gap waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 4; hex 0000000a; asc     ;;
 1: len 6; hex 00000003bf87; asc       ;;
 2: len 7; hex 81000001890110; asc        ;;
 3: len 4; hex 80000065; asc    e;;

2024-08-04T07:51:55.787944Z 0 [Note] [MY-012469] [InnoDB] *** WE ROLL BACK TRANSACTION (2)

3. 详细分析

3.1 辅助信息

2024-08-04T07:51:55.786277Z 0 [Note] [MY-012468] [InnoDB] 
  Transactions deadlock detected, dumping detailed information.

2024-08-04T07:51:55.786346Z 0 [Note] [MY-012469] [InnoDB] 
  *** (1) TRANSACTION:
  ...
2024-08-04T07:51:55.786433Z 0 [Note] [MY-012469] [InnoDB] 
  *** (1) HOLDS THE LOCK(S):
  ...
2024-08-04T07:51:55.786800Z 0 [Note] [MY-012469] [InnoDB] 
  *** (1) WAITING FOR THIS LOCK TO BE GRANTED:
2024-08-04T07:51:55.787156Z 0 [Note] [MY-012469] [InnoDB] 
  ...
  *** (2) TRANSACTION:
2024-08-04T07:51:55.787237Z 0 [Note] [MY-012469] [InnoDB] 
  *** (2) HOLDS THE LOCK(S):
  ...
2024-08-04T07:51:55.787586Z 0 [Note] [MY-012469] [InnoDB] 
  *** (2) WAITING FOR THIS LOCK TO BE GRANTED:
  ...
2024-08-04T07:51:55.787944Z 0 [Note] [MY-012469] [InnoDB] 
  *** WE ROLL BACK TRANSACTION (2)

以上是从死锁日志中择（zhái）出来的辅助信息。只有系统变量 log_error_verbosity 的值为 3，死锁日志中才会包含这些信息。

辅助信息告知我们紧随其后的日志是什么类型的信息。例如：(1) TRANSACTION 告知我们紧随其后的是事务信息。

我们先来看看每条辅助日志的前 5 项表明什么。以第 1 条日志为例，前 5 项如下：

/* 第 1 项 */ 2024-08-04T07:51:55.786277Z
/* 第 2 项 */ 0
/* 第 3 项 */ [Note]
/* 第 4 项 */ [MY-012468]
/* 第 5 项 */ [InnoDB]

第 1 项，产生这条日志的时间，准确到毫秒。

第 2 项，线程 ID。由于 InnoDB 调用 ib::info() 方法把辅助信息写入 MySQL 错误日志文件，ib::info() 没有设置正确的线程 ID，所以这一项总是为 0。

第 3 项，日志级别。由于辅助信息都是 information_level 级别，所以这一项总是 Note。

第 4 项，前缀 MY- 加错误码。代码里是这样写辅助信息中第 1 条日志的：

ib::info(ER_IB_MSG_643)
  << "Transactions deadlock detected, dumping"
  << " detailed information.";

ER_IB_MSG_643 的定义如下：

#define ER_IB_MSG_643 12468

前缀 MY- 加上错误码 12468，就变成了 MY-012468。

第 5 项，子系统名称。InnoDB 产生的日志，子系统名称当然就是 InnoDB 了。

介绍完每条日志的前 5 项，我们再来看看为死锁环中每个事务生成的事务信息、持有的行锁信息、等待中的行锁信息。

/* 第 1 部分 */
*** (N) TRANSACTION:
/* 第 2 部分 */
*** (N) HOLDS THE LOCK(S):
/* 第 3 部分 */
*** (N) WAITING FOR THIS LOCK TO BE GRANTED:

由于死锁环中每个事务都会有这三部分信息，所以我把括号里的数字替换成 N 了。

第 1 部分，事务本身的信息、加锁的概要信息。

第 2 部分，事务持有的行锁信息、加锁记录信息。

死锁环中，事务（X）持有某条记录（R1）的行锁，阻塞了另一个事务获得这条记录的行锁。

如果事务 X 还持有 R1 所在数据页中其它记录的行锁，事务 X 的第 2 部分会包含 R1 和这些加锁记录的信息。

所以，第 2 部分可能会包含一条或多条记录的信息。

第 3 部分，事务正在等待获得的行锁信息、加锁记录信息。

这部分包含处于等待状态的行锁信息，以及一条加锁记录的信息。

由于处于等待状态的行锁结构，不能共用，所以只会包含一条加锁记录。

介绍完死锁环中每个事务的三部分信息，接下来的辅助信息很重大，就是哪个事务被选择成为死锁受害事务了。

2024-08-04T07:51:55.787944Z 0 [Note] [MY-012469] [InnoDB] 
  *** WE ROLL BACK TRANSACTION (2)

从以上辅助信息可以看到，事务 2 被选择成为死锁受害事务了。

3.2 事务信息

TRANSACTION 246047, ACTIVE 7 sec 
  starting index read

TRANSACTION 后面的数字，表明事务 ID，来自事务对象的 id 属性。

ACTIVE 表明事务处于活跃状态，来自事务对象的 state 属性。

sec 前面的数字，表明事务活跃的时间。用产生这条日志的时间，减去事务对象 start_time 属性中保存的事务开始时间得到。

starting index read 表明事务正在准备读取索引记录，来自事务对象的 op_info 属性。如果事务正在做其它事情，这里就会变为其它内容了。

mysql tables in use 1, locked 1

mysql tables in use 后面的数字，表明事务正在执行的 SQL 语句会操作几个表。

locked 后面的数字，表明事务正在执行的 SQL 语句会对几个表加表锁。对于 select、insert、update、delete 语句，这里的表锁一般都是指的意向共享锁或者意向排他锁。

LOCK WAIT 3 lock struct(s), 
  heap size 1192, 2 row lock(s)

LOCK WAIT 表明事务加锁处于等待状态，等待获得表锁或者行锁，都会写入这一项。

lock struct(s) 前面的数字，表明事务使用了几个锁结构（包含表锁结构和行锁结构），来自事务对象 trx_locks 链表中的锁结构数量。

heap size 后面的数字，表明事务对象用于创建新的表锁结构和行锁结构的堆内存大小，1192 是调试环境 Debug 版本的初始大小，单位是字节。

如果是线上环境 Release 版本的 MySQL，初始大小是 1156 字节。

如果这块内存不够用了，InnoDB 会扩大这块内存，那样的话，我们看到的 heap size 就会大于 1192 或者 1156。

row lock(s) 前面的数字，表明事务加行锁的记录数量（包含已经获得锁、等待获得锁的记录）。

MySQL thread id 8, 
  OS thread handle 123145473822720, 
  query id 136 
  localhost 127.0.0.1 
  root 
  statistics 
  SELECT i1 FROM t1 WHERE id = 20 FOR UPDATE

以上日志是执行事务的线程信息。

MySQL thread id 后面的数字，是 MySQL 分配给线程的 ID，用于 MySQL 内部标识一个线程。

OS thread handle 后面的数字，是操作系统分配的线程 ID。

query id 后面的数字，是 MySQL 当前执行的 SQL 语句 ID。

这个 ID 从 1 开始，每执行一条 SQL 语句就加 1。换句话说，它表明 MySQL 正在执行本次启动以来的第几条 SQL 语句。

localhost 127.0.0.1 是客户端的主机名和 IP 地址。如果没有获取到主机名，localhost 的位置就不会显示了。

statistics 是线程当前正在做的事情，来自 server 层线程对象的 m_proc_info 属性，和事务对象的 op_info 属性值不同。

最后是线程当前正在执行的 SQL 语句，也就是导致死锁的 SQL 语句。

3.3 行锁信息

RECORD LOCKS 
  space id 0 
  page no 46 
  n bits 72 
  index PRIMARY of table `test`.`t1` 
  trx id 246047 
  lock_mode X 
  locks rec but not gap

RECORD LOCKS 表明接下来的是行锁信息。

space id 后面的数字，表明加锁记录所属表的表空间 ID。示例 SQL 中 t1 表位于系统表空间，所以表空间 ID 为 0。

page no 后面的数字，表明加锁记录所属数据页的页号。

n bits 后面的数字，表明加锁记录对应行锁结构的 bitmap 内存区域有多少位，可以标识多少条记录是否加锁。这个数字除以 8 就是 bitmap 内存区域占用的字节数。

index PRIMARY of table `test`.`t1` 表明事务对哪个数据库中哪个表的主键索引记录加锁。

如果是对二级索引记录加锁，PRIMARY 处就是二级索引名了。

trx id 后面的数字，表明加锁的事务 ID。

lock_mode 表明行锁的模式，共享锁为 X，排他锁为 S。

locks rec but not gap 表明行锁的准确模式为普通记录锁。

如果是间隙锁，这里会改为 locks gap before rec。

如果是插入意向锁，这里会改为 insert intention。

如果是 Next-Key 锁，这个位置就不会显示任何内容了。

如果事务对这条记录加行锁，处于锁等待状态，在行锁的准确模式之后还会显示 waiting。

Record lock, heap no 2 
  PHYSICAL RECORD: n_fields 4; compact format; info bits 0
0: len 4; hex 0000000a; asc     ;;
1: len 6; hex 00000003bf87; asc       ;;
2: len 7; hex 81000001890110; asc        ;;
3: len 4; hex 80000065; asc    e;;

以上日志表明一条加锁记录的信息。

对于已经获得锁的行锁结构，可能会包含一条或多条加锁记录的信息。

对于处于锁等待状态的行锁结构，只有一条加锁记录的信息。

Record lock 表明加锁记录。

heap no 后面的数字，表明加锁记录在其所属数据页中的编号。这个编号跟记录的物理顺序和逻辑顺序都没有关系，只是用来唯一标识数据页中一条记录。

PHYSICAL RECORD 表明接下来的是物理记录信息。

n_fields 后面的数字，表明物理记录的字段数量。

compact format 表明记录的格式是 compact、dynamic、compressed 三者之一。

如果记录的格式是 redundant，compact format 会变为 1-byte offsets format 或者 2-byte offsets format。

info bits 包含两个标志位：记录的删除标志、B+ 树索引非叶子结点中当前层级最小的用户记录标志。这一项的值为 0，说明两个标志位都没有设置。

接下来就是物理记录中各字段的长度和内容了。

示例 SQL 中，t1 表只有 id、i1 两个字段，日志中却记录了 4 个字段，这是由于 InnoDB 记录还包含 DB_TRX_ID（事务 ID）、DB_ROLL_PTR（undo 日志地址）两个额外字段。

DB_TRX_ID、DB_ROLL_PTR 总是位于主键字段之后。对于 t1 表，以上日志对应的字段如下：

-- id
0: len 4; hex 0000000a; asc     ;;
-- DB_TRX_ID
1: len 6; hex 00000003bf87; asc       ;;
-- DB_ROLL_PTR
2: len 7; hex 81000001890110; asc        ;;
-- i1
3: len 4; hex 80000065; asc    e;;

每个字段的内容都以 16 进制显示，如果字段为无符号整数类型（create table 或者 alter table 为字段指定了 unsigned 关键字），字段内容加上前缀 0x，再转换为十进制就可以得到整数值。

> 说明：DB_TRX_ID、DB_ROLL_PTR 都是无符号整数类型。

以上面日志中 id 字段为例，在 shell 命令行中执行以下命令就可以得到整数值：

## 输出结果为 10
echo $((0x0000000a))

如果字段为有符号整数类型，字段内容加上前缀 0x，并对符号位进行异或操作，再转换为十进制就可以得到整数值。

以上面日志中 i1 字段为例，在 shell 命令行中执行以下命令就可以得到整数值：

## ^ 表明【异或】操作
## 4 是 i1 字段的长度，表明 4 字节
## 符号是是最高位，4 字节的符号位是第 32 位（4 * 8 = 32）
## 1 左移（<<）31 位（32 - 1 = 31）就是符号位
## 输出结果为 101
echo $((0x80000065 ^ (1 << (4 * 8 - 1))))