死锁分析

闲话：小青蛙很久没发文，不是小孩子挂了，是小孩子正在着急改稿子，准备出《MySQL是怎样运行的：从根儿上理解MySQL》的纸质书，在小册的基础上增删了一个半月，上周日终于改完了。这本破书从去年三月算是正式开始（之前也写了一些内容，但不正式），耗费了我一年多的青春时光，一年多的007工作制，只为了给大家一个不错的学习体验，让那些晦涩难懂的知识变得简单自然。原创文章写起来很费时，短则数个小时，长则数周，原创不易，且看且珍惜（不是我不想转载，实在是没什么能转的）。

注意：本篇文章适宜在电脑上观看。

如果我们的业务处在一个非常初级的阶段，并发程度比较低，那么我们可以几年都遇不到一次死锁问题的发生，反之，我们业务的并发程度非常高，那么时不时爆出的死锁问题肯定让我们非常挠头。不过在死锁问题发生时，很多没有经验的同学的第一反应就是成为一只鸵鸟：这玩意儿很高深，我也看不懂，听天由命吧，又不是一直发生。其实如果大家认真研读了我们之前写的3篇关于 MySQL 中语句加锁分析的文章：

加上本篇关于死锁日志的分析，那么解决死锁问题应该也不是那么摸不着头脑的事情了。

准备工作

为了故事的顺利发展，我们需要建一个表：

CREATE TABLE hero (
    id INT,
    name VARCHAR(100),
    country varchar(100),
    PRIMARY KEY (id),
    KEY idx_name (name)
) Engine=InnoDB CHARSET=utf8;

我们为hero表的id列创建了聚簇索引，为name列创建了一个二级索引。这个hero表主要是为了存储三国时的一些英雄，我们向表中插入一些记录：

INSERT INTO hero VALUES
    (1, 'l刘备', '蜀'),
    (3, 'z诸葛亮', '蜀'),
    (8, 'c曹操', '魏'),
    (15, 'x荀彧', '魏'),
    (20, 's孙权', '吴');

现在表中的数据就是这样的：

mysql> SELECT * FROM hero;
+----+------------+---------+
| id | name       | country |
+----+------------+---------+
|  1 | l刘备      | 蜀      |
|  3 | z诸葛亮    | 蜀      |
|  8 | c曹操      | 魏      |
| 15 | x荀彧      | 魏      |
| 20 | s孙权      | 吴      |
+----+------------+---------+
5 rows in set (0.00 sec)

准备工作就做完了。

创建死锁情景

我们先创建一个发生死锁的情景，在 Session A 和 Session B 中分别执行两个事务，具体情况如下：

我们分析一下：

从第③步中可以看出， Session A 中的事务先对 hero 表聚簇索引的 id 值为1的记录加了一个 X型正经记录锁 。
从第④步中可以看出， Session B 中的事务对 hero 表聚簇索引的 id 值为3的记录加了一个 X型正经记录锁 。
从第⑤步中可以看出， Session A 中的事务接着想对 hero 表聚簇索引的 id 值为3的记录也加了一个 X型正经记录锁 ，但是与第④步中 Session B 中的事务加的锁冲突，所以 Session A 进入阻塞状态，等待获取锁。
从第⑥步中可以看出， Session B 中的事务想对 hero 表聚簇索引的 id 值为1的记录加了一个 X型正经记录锁 ，但是与第③步中 Session A 中的事务加的锁冲突，而此时 Session A 和 Session B 中的事务循环等待对方持有的锁，死锁发生，被 MySQL 服务器的死锁检测机制检测到了，所以选择了一个事务进行回滚，并向客户端发送一条消息：
```
ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction
```

以上是我们从语句加了什么锁的角度出发来进行死锁情况分析的，但是实际应用中我们可能压根儿不知道到底是哪几条语句产生了死锁，我们需要根据 MySQL 在死锁发生时产生的死锁日志来逆向定位一下到底是什么语句产生了死锁，从而再优化我们的业务。

查看死锁日志

设计 InnoDB 的大叔给我们提供了 SHOW ENGINE INNODB STATUS 命令来查看关于InnoDB存储引擎的一些状态信息，其中就包括了系统最近一次发生死锁时的加锁情况。在上边例子中的死锁发生时，我们运行一下这个命令：

mysql> SHOW ENGINE INNODB STATUS\G
...省略了好多其他信息
------------------------
LATEST DETECTED DEADLOCK
------------------------
2019-06-20 13:39:19 0x70000697e000
*** (1) TRANSACTION:
TRANSACTION 30477, ACTIVE 10 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1160, 2 row lock(s)
MySQL thread id 2, OS thread handle 123145412648960, query id 46 localhost 127.0.0.1 root statistics
select * from hero where id = 3 for update
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 171 page no 3 n bits 72 index PRIMARY of table `dahaizi`.`hero` trx id 30477 lock_mode X locks rec but not gap waiting
Record lock, heap no 3 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
 0: len 4; hex 80000003; asc     ;;
 1: len 6; hex 000000007517; asc     u ;;
 2: len 7; hex 80000001d0011d; asc        ;;
 3: len 10; hex 7ae8afb8e8919be4baae; asc z         ;;
 4: len 3; hex e89c80; asc    ;;

*** (2) TRANSACTION:
TRANSACTION 30478, ACTIVE 8 sec starting index read
mysql tables in use 1, locked 1
3 lock struct(s), heap size 1160, 2 row lock(s)
MySQL thread id 3, OS thread handle 123145412927488, query id 47 localhost 127.0.0.1 root statistics
select * from hero where id = 1 for update
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 171 page no 3 n bits 72 index PRIMARY of table `dahaizi`.`hero` trx id 30478 lock_mode X locks rec but not gap
Record lock, heap no 3 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
 0: len 4; hex 80000003; asc     ;;
 1: len 6; hex 000000007517; asc     u ;;
 2: len 7; hex 80000001d0011d; asc        ;;
 3: len 10; hex 7ae8afb8e8919be4baae; asc z         ;;
 4: len 3; hex e89c80; asc    ;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 171 page no 3 n bits 72 index PRIMARY of table `dahaizi`.`hero` trx id 30478 lock_mode X locks rec but not gap waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
 0: len 4; hex 80000001; asc     ;;
 1: len 6; hex 000000007517; asc     u ;;
 2: len 7; hex 80000001d00110; asc        ;;
 3: len 7; hex 6ce58898e5a487; asc l      ;;
 4: len 3; hex e89c80; asc    ;;

*** WE ROLL BACK TRANSACTION (2)
------------
...省略了好多其他信息

我们只关心最近发生的死锁信息，所以就把以 LATEST DETECTED DEADLOCK 这一部分给单独提出来分析一下。下边我们就逐行看一下这个输出的死锁日志都是什么意思：

首先看第一句：
```
2019-06-20 13:39:19 0x70000697e000
```
这句话的意思就是死锁发生的时间是：2019-06-20 13:39:19，后边的一串十六进制 0x70000697e000 表示的操作系统为当前session分配的线程的线程id。

然后是关于死锁发生时第一个事务的有关信息：

*** (1) TRANSACTION:

# 为事务分配的id为30477
# 事务处于ACTIVE状态已经10秒了
# 事务现在正在做的操作就是：“starting index read”
TRANSACTION 30477, ACTIVE 10 sec starting index read

# 此事务使用了1个表，为1个表上了锁（此处不是说为该表加了表锁，只要不是进行一致性读的表，都需要加锁，具体怎么加锁请看加锁语句分析或者小册章节）
mysql tables in use 1, locked 1

# 此事务处于LOCK WAIT状态，拥有3个锁结构（2个行锁结构，1个表级别X型意向锁结构，锁结构在小册中重点介绍过）
# heap size是为了存储锁结构而申请的内存大小（我们可以忽略），其中有2个行锁的结构
LOCK WAIT 3 lock struct(s), heap size 1160, 2 row lock(s)

# 本事务所在线程的id是2（MySQL自己命名的线程id），该线程在操作系统级别的id就是那一长串数字
# 当前查询的id为46（MySQL内部使用，可以忽略），还有用户名主机信息
MySQL thread id 2, OS thread handle 123145412648960, query id 46 localhost 127.0.0.1 root statistics

# 本事务发生阻塞的语句
select * from hero where id = 3 for update

# 本事务当前在等待获取的锁：
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:

# 等待获取的表空间ID为151，页号为3，也就是表hero的PRIMAY索引中的某条记录的锁
# n_bits是为了存储本页面的锁信息而分配的一串内存空间，小册中有详细介绍
# 该锁的类型是X型正经记录锁（rec but not gap）
RECORD LOCKS space id 171 page no 3 n bits 72 index PRIMARY of table `dahaizi`.`hero` trx id 30477 lock_mode X locks rec but not gap waiting

# 该记录在页面中的heap_no为2，具体的记录信息如下：
Record lock, heap no 3 PHYSICAL RECORD: n_fields 5; compact format; info bits 0

# 这是主键值
0: len 4; hex 80000003; asc     ;;

# 这是trx_id隐藏列
1: len 6; hex 000000007517; asc     u ;;

# 这是roll_pointer隐藏列
2: len 7; hex 80000001d0011d; asc        ;;

# 这是name列
3: len 10; hex 7ae8afb8e8919be4baae; asc z         ;;

# 这是country列
4: len 3; hex e89c80; asc    ;;

从这个信息中可以看出， Session A 中的事务为2条记录生成了锁结构，但是其中有一条记录上的 X型正经记录锁 （rec but not gap）并没有获取到，没有获取到锁的这条记录的位置是：表空间ID为151，页号为3，heap_no为2。当然，设计 InnoDB 的大叔还贴心的给出了这条记录的详细情况，它的主键值为 80000003 ，这其实是InnoDB内部存储使用的格式，其实就代表数字 3 ，也就是该事务在等待获取 hero 表聚簇索引主键值为 3 的那条记录的 X型 正经记录锁。

然后是关于死锁发生时第二个事务的有关信息：

其中的大部分信息我们都已经介绍过了，我们就挑重要的说：

*** (2) TRANSACTION:
TRANSACTION 30478, ACTIVE 8 sec starting index read
mysql tables in use 1, locked 1
3 lock struct(s), heap size 1160, 2 row lock(s)
MySQL thread id 3, OS thread handle 123145412927488, query id 47 localhost 127.0.0.1 root statistics
select * from hero where id = 1 for update

# 表示该事务获取到的锁信息
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 171 page no 3 n bits 72 index PRIMARY of table `dahaizi`.`hero` trx id 30478 lock_mode X locks rec but not gap
Record lock, heap no 3 PHYSICAL RECORD: n_fields 5; compact format; info bits 0

# 主键值为3
0: len 4; hex 80000003; asc     ;;
1: len 6; hex 000000007517; asc     u ;;
2: len 7; hex 80000001d0011d; asc        ;;
3: len 10; hex 7ae8afb8e8919be4baae; asc z         ;;
4: len 3; hex e89c80; asc    ;;

# 表示该事务等待获取的锁信息
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 171 page no 3 n bits 72 index PRIMARY of table `dahaizi`.`hero` trx id 30478 lock_mode X locks rec but not gap waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 5; compact format; info bits 0

# 主键值为1
0: len 4; hex 80000001; asc     ;;
1: len 6; hex 000000007517; asc     u ;;
2: len 7; hex 80000001d00110; asc        ;;
3: len 7; hex 6ce58898e5a487; asc l      ;;
4: len 3; hex e89c80; asc    ;;

从上边的输出可以看出来， Session B 中的事务获取了 hero 表聚簇索引主键值为 3 的记录的 X型正经记录锁 ，等待获取 hero 表聚簇索引主键值为 1 的记录的 X型正经记录锁 （隐含的意思就是这个 hero 表聚簇索引主键值为 1 的记录的 X型正经记录锁 已经被 SESSION A 中的事务获取到了）。

看最后一部分：
```
*** WE ROLL BACK TRANSACTION (2)
```
最终InnoDB存储引擎决定回滚第2个事务，也就是 Session B 中的那个事务。

思索分析的思路

查看死锁日志时，首先看一下发生死锁的事务等待获取锁的语句都是啥。

本例中，发现 SESSION A 发生阻塞的语句是：
```
select * from hero where id = 3 for update
```
SESSION B 发生阻塞的语句是：
```
select * from hero where id = 1 for update
```
然后切记：到自己的业务代码中找出这两条语句所在事务的其他语句。
找到发生死锁的事务中所有的语句之后，对照着事务获取到的锁和正在等待的锁的信息来分析死锁发生过程。

从死锁日志中可以看出来， SESSION A 获取了 hero 表聚簇索引 id 值为1的记录的 X型正经记录锁 （这其实是从 SESSION B 正在等待的锁中获取的），查看 SESSION A 中的语句，发现是下边这个语句造成的（对照着语句加锁分析那三篇文章）:
```
select * from hero where id = 1 for update;
```
还有 SESSION B 获取了 hero 表聚簇索引 id 值为3的记录的 X型正经记录锁 ，查看 SESSION B 中的语句，发现是下边这个语句造成的（对照着语句加锁分析那三篇文章）:
```
select * from hero where id = 3 for update;
```
然后看 SESSION A 正在等待 hero 表聚簇索引 id 值为3的记录的 X型正经记录锁 ，这个是由于下边这个语句造成的：
```
select * from hero where id = 3 for update;
```
然后看 SESSION B 正在等待 hero 表聚簇索引 id 值为1的记录的 X型正经记录锁 ，这个是由于下边这个语句造成的：
```
select * from hero where id = 1 for update;
```
然后整个死锁形成过程就根据死锁日志给还原出来了。

准备工作

创建死锁情景

查看死锁日志

思索分析的思路

Recommend

Parse APK/IPA file information by js

SpringBoot 初始化之7招式-美码师

ceph节点journal盘更换-潇洒哥来啦的博客

[译] Chrome 专家调试法

友讯科技同意实现新的安全程序以和解 FTC 诉讼

美国仍按被拉黑企业对待华为

印度理工学院发布其开源处理器的 SDK

小米威胁起诉声称 Mimoji 抄袭苹果 Memoji 的网民

Deprecation message support for PHPStan | matt glaman

安卓之父遭妻子指控：至少有5名情妇婚前协议不公

About Joyk