MySQL 死锁日志详解

原创
08/21 10:48
阅读数 3.9K

> 作者:操盛春,爱可生技术专家,公众号『一树一溪』作者,专注于研究 MySQL 和 OceanBase 源码。 > >爱可生开源社区出品,原创内容未经授权不得随意使用,转载请联系小编并注明来源。

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

目录 [TOC]

正文

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. 总结

没有需要总结的内容了,但是,总结 这一小节不能少,因为仪式感还是要有的。

更多技术文章,请访问:https://opensource.actionsky.com/

关于 SQLE

SQLE 是一款全方位的 SQL 质量管理平台,覆盖开发至生产环境的 SQL 审核和管理。支持主流的开源、商业、国产数据库,为开发和运维提供流程自动化能力,提升上线效率,提高数据质量。

✨ Github:https://github.com/actiontech/sqle

📚 文档:https://actiontech.github.io/sqle-docs/

💻 官网:https://opensource.actionsky.com/sqle/

👥 微信群:请添加小助手加入 ActionOpenSource

🔗 商业支持:https://www.actionsky.com/sqle

展开阅读全文
加载中
点击引领话题📣 发布并加入讨论🔥
0 评论
2 收藏
4
分享
返回顶部
顶部