分析一下MySQL 死锁日志

北欧人写代码

于 2024-09-02 08:15:00 发布

阅读量1k

点赞数 18

文章标签： mysql 数据库

本文链接：https://blog.csdn.net/qq_33257158/article/details/141789763

版权

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)
  &lt;&lt; "Transactions deadlock detected, dumping"
  &lt;&lt; " 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 左移（&lt;&lt;）31 位（32 - 1 = 31）就是符号位
## 输出结果为 101
echo $((0x80000065 ^ (1 &lt;&lt; (4 * 8 - 1))))