死锁日志里那么多信息，都表示什么意思？
作者：操盛春，爱可生技术专家，公众号『一树一溪』作者，专注于研究 MySQL 和 OceanBase 源码。
爱可生开源社区出品，原创内容未经授权不得随意使用，转载请联系小编并注明来源。
本文基于 MySQL 8.0.32 源码，存储引擎为 InnoDB。
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))))
4. 总结
没有需要总结的内容了，但是，总结 这一小节不能少，因为仪式感还是要有的。
