> 作者:操盛春,爱可生技术专家,公众号『一树一溪』作者,专注于研究 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