死锁分析

zhangdeTalk 的个人博客 / 2 / 0 / 创建于 5年前 / 更新于 5年前

如果我们的业务处在一个非常初级的阶段，并发程度比较低，那么我们可以几年都遇不到一次死锁问题的发生，反之，我们业务的并发程度非常高，那么时不时爆出的死锁问题肯定让我们非常挠头。不过在死锁问题发生时，很多没有经验的同学的第一反应就是成为一只鸵鸟：这玩意儿很高深，我也看不懂，听天由命吧，又不是一直发生。其实如果大家认真研读了我们之前写的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 readmysql tables in use 1, locked 1LOCK 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 statisticsselect * 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 waitingRecord 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 readmysql tables in use 1, locked 13 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 statisticsselect * 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 gapRecord 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 waitingRecord 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 readmysql tables in use 1, locked 13 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 statisticsselect * 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 gapRecord lock, heap no 3 PHYSICAL RECORD: n_fields 5; compact format; info bits 0# 主键值为30: 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 waitingRecord lock, heap no 2 PHYSICAL RECORD: n_fields 5; compact format; info bits 0# 主键值为10: 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;
```
然后整个死锁形成过程就根据死锁日志给还原出来了。