如何读懂MySQL死锁日志

分手后的思念是犯贱 2022-11-26 06:58 190阅读 0赞

# 测试环境 #

CREATE TABLE `test` (
    	`id` INT(10) NOT NULL,
    	`str` VARCHAR(50),
    	`value` VARCHAR(50),
    	PRIMARY KEY (`id`),
    	UNIQUE INDEX `str` (`str`)
    )
    COLLATE='utf8_general_ci'
    ENGINE=InnoDB
    ;
    
    INSERT INTO `test` (`id`, `str`, `value`) VALUES (10234567, '1sdfsdfsdfsdfsdfsdfsdfsdfsdflkj;lkjlkhjs;lfgdg', NULL);
    INSERT INTO `test` (`id`, `str`, `value`) VALUES (20023456, '2werwerwerwerwerwerweoijonsfoihdighoiusdhgpisud', NULL);
    INSERT INTO `test` (`id`, `str`, `value`) VALUES (30123456, '3sdfsdfsdfsdf', NULL);

# 互相等待行锁 #

**创建死锁现场**

会话1执行：

mysql> begin;select * from test where id = 10234567  for update;
    Query OK, 0 rows affected (0.00 sec)
    
    +----------+-------+---------------------+--------------------------------------------+
    | id       | value | datetime            | str                                            |
    +----------+-------+---------------------+---------------------------------------------+
    | 10234567 |   100 | 2020-08-10 18:31:12 | 1sdfsdfsdfsdfsdfsdfsdfsdfsdflkj;lkjlkhjs;lfgdg |
    +----------+-------+---------------------+---------------------------------------------+
    1 row in set (0.00 sec)

会话2执行：

mysql> begin;select * from test where id = 20023456  for update;        
    Query OK, 0 rows affected (0.00 sec)
    
    +----------+-------+---------------------+--------------------------------------------+
    | id       | value | datetime            | str                                             |
    +----------+-------+---------------------+--------------------------------------------+
    | 20023456 |   100 | 2020-08-10 18:31:24 | 2werwerwerwerwerwerweoijonsfoihdighoiusdhgpisud |
    +----------+-------+---------------------+-------------------------------------------+
    1 row in set (0.00 sec)

会话1继续执行：

mysql> select * from test where id = 20023456  for update;

会话1阻塞…

会话2继续执行：

mysql> select * from test where id = 10234567  for update;
    ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction

**显示发生死锁**，同时会话1返回并输入：

+----------+-------+---------------------+--------------------------------- -----------+
    | id       | value | datetime            | str                                             |
    +----------+-------+---------------------+---------------------------------------------+
    | 20023456 |   100 | 2020-08-10 18:31:24 | 2werwerwerwerwerwerweoijonsfoihdighoiusdhgpisud |
    +----------+-------+---------------------+---------------------------------------------+
    1 row in set (5.02 sec)

**死锁日志分析**

执行如下命令【show engine innodb status 】可看到最近一次死锁日志，也可以通过【set global innodb\_print\_all\_deadlocks=on】命令记录全部死锁信息到【log\_error 】指向的日志文件中，上述死锁的日志如下：

LATEST DETECTED DEADLOCK
    ------------------------
    2020-08-10 18:50:18 0x7fb726fa5700
    *** (1) TRANSACTION:
    TRANSACTION 110686664, ACTIVE 12 sec starting index read
    mysql tables in use 1, locked 1
    LOCK WAIT 3 lock struct(s), heap size 1136, 2 row lock(s)
    MySQL thread id 347214, OS thread handle 140424592910080, query id 238824800 localhost root statistics
    select * from test where id = 20023456  for update
    *** (1) WAITING FOR THIS LOCK TO BE GRANTED:
    RECORD LOCKS space id 79351 page no 3 n bits 72 index PRIMARY of table `ssmdemo`.`test` trx id 110686664 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 013188a0; asc  1  ;;
     1: len 6; hex 00000698f1a6; asc       ;;
     2: len 7; hex c00000021f0110; asc        ;;
     3: len 30; hex 3277657277657277657277657277657277657277656f696a6f6e73666f69; asc 2werwerwerwerwerwerweoijonsfoi; (total 47 bytes);
    
    *** (2) TRANSACTION:
    TRANSACTION 110686665, ACTIVE 9 sec starting index read
    mysql tables in use 1, locked 1
    3 lock struct(s), heap size 1136, 2 row lock(s)
    MySQL thread id 347255, OS thread handle 140424609683200, query id 238824801 localhost root statistics
    select * from test where id = 10234567  for update
    *** (2) HOLDS THE LOCK(S):
    RECORD LOCKS space id 79351 page no 3 n bits 72 index PRIMARY of table `ssmdemo`.`test` trx id 110686665 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 013188a0; asc  1  ;;
     1: len 6; hex 00000698f1a6; asc       ;;
     2: len 7; hex c00000021f0110; asc        ;;
     3: len 30; hex 3277657277657277657277657277657277657277656f696a6f6e73666f69; asc 2werwerwerwerwerwerweoijonsfoi; (total 47 bytes);
    
    *** (2) WAITING FOR THIS LOCK TO BE GRANTED:
    RECORD LOCKS space id 79351 page no 3 n bits 72 index PRIMARY of table `ssmdemo`.`test` trx id 110686665 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 009c2ac7; asc   * ;;
     1: len 6; hex 00000698f1a4; asc       ;;
     2: len 7; hex bf000001300110; asc     0  ;;
     3: len 30; hex 317364667364667364667364667364667364667364667364667364666c6b; asc 1sdfsdfsdfsdfsdfsdfsdfsdfsdflk; (total 46 bytes);
    
    *** WE ROLL BACK TRANSACTION (2)

我们来看看这日志中的几个关键信息，

1、这个结果分成三部分：

(1) TRANSACTION，是第一个事务的信息；

(2) TRANSACTION，是第二个事务的信息；

(3)WE ROLL BACK TRANSACTION (2)，是最终的处理结果，表示回滚了第2个事务。

2、第一个事务的信息中：

*  select 语句是这个事务正在执行的语句；
 *  WAITING FOR THIS LOCK TO BE GRANTED，表示的是这个事务正在等待的锁信息；
 *  index PRIMARY of table，说明在等的是表的主键索引上的锁；
 *  lock\_mode X locks rec but not gap waiting 表示这个事务正在等待的是行锁；
 *  Record lock 说明这是一个记录锁；
 *  n\_fields 4 表示这个记录有4列，靠前的是索引信息
 *  0: len 4; hex 013188a0; asc 1 ;; 也就是主键 id，转换为10进制后是**20023456**；这里的 asc 表示的是，接下来要打印出值里面的“需打印字符”，但主键是整数，不需打印，因此就显示空格，如果是字符串类型的字段，则这里会显示字符串内容，但是asc只有4字节，因此可能只打印字符串前缀。
 *  第一个事务信息就只显示出了等锁的状态，在等待 (id=20023456) 行锁。
 *  当然你是知道的，既然出现死锁了，就表示这个事务也占有别的锁，但是没有显示出来。别着急，我们从第二个事务的信息中推导出来。

3、第二个事务显示的信息要多一些：

*  “ HOLDS THE LOCK(S)”用来显示这个事务持有哪些锁；
 *  index PRIMARY of table 表示持有锁主键索引 上的锁；
 *  0: len 4; hex 013188a0; asc 1 ;; 表示这个事务持有 id=20023456的记录锁；
 *  WAITING FOR THIS LOCK TO BE GRANTED，表示在等 id=10234567的记录锁。

从上面这些信息中，我们可知道：

事务1正在执行【select \* from test where id = 20023456 for update】语句，持有 id=10234567 的行锁，等待id=20023456的行锁。

事务2正在执行【select \* from test where id = 10234567 for update】语句，持有id=20023456的行锁，等待 id=10234567 的行锁。

因此导致了死锁。

# asc打印字段值 #

和分析1一样的测试环境。

会话1执行：

mysql> begin; update test set str = "111111111" where str = "1sdfsdfsdfsdfsdfsdfsdfsdfsdflkj;lkjlkhjs;lfgdg";       
    Query OK, 0 rows affected (0.00 sec)
    
    Query OK, 1 row affected (0.00 sec)
    Rows matched: 1  Changed: 1  Warnings: 0

会话2执行：

mysql> begin; update test set str = "3333333" where str = '3sdfsdfsdfsdf';        
    Query OK, 0 rows affected (0.00 sec)
    
    Query OK, 1 row affected (0.00 sec)
    Rows matched: 1  Changed: 1  Warnings: 0

会话1继续执行：

update test set str = "3333333" where str = '3sdfsdfsdfsdf';

会话1被阻塞，会话2继续执行：

mysql> update test set str = "111111111" where str = "1sdfsdfsdfsdfsdfsdfsdfsdfsdflkj;lkjlkhjs;lfgdg";  
    ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction

检测到死锁，会话1返回并输出：

Query OK, 1 row affected (10.72 sec)
    Rows matched: 1  Changed: 1  Warnings: 0

死锁日志如下：

------------------------
    LATEST DETECTED DEADLOCK
    ------------------------
    2020-08-10 19:23:54 0x7fb726fa5700
    *** (1) TRANSACTION:
    TRANSACTION 110687265, ACTIVE 60 sec starting index read
    mysql tables in use 1, locked 1
    LOCK WAIT 4 lock struct(s), heap size 1136, 3 row lock(s), undo log entries 1
    MySQL thread id 347214, OS thread handle 140424592910080, query id 238841635 localhost root updating
    update test set str = "3333333" where str = '3sdfsdfsdfsdf'
    *** (1) WAITING FOR THIS LOCK TO BE GRANTED:
    RECORD LOCKS space id 79351 page no 4 n bits 80 index str of table `ssmdemo`.`test` trx id 110687265 lock_mode X waiting
    Record lock, heap no 6 PHYSICAL RECORD: n_fields 2; compact format; info bits 32
     0: len 13; hex 33736466736466736466736466; asc 3sdfsdfsdfsdf;;
     1: len 4; hex 01cba5c0; asc     ;;
    
    *** (2) TRANSACTION:
    TRANSACTION 110687270, ACTIVE 53 sec starting index read
    mysql tables in use 1, locked 1
    4 lock struct(s), heap size 1136, 3 row lock(s), undo log entries 1
    MySQL thread id 347255, OS thread handle 140424609683200, query id 238841636 localhost root updating
    update test set str = "111111111" where str = "1sdfsdfsdfsdfsdfsdfsdfsdfsdflkj;lkjlkhjs;lfgdg"
    *** (2) HOLDS THE LOCK(S):
    RECORD LOCKS space id 79351 page no 4 n bits 80 index str of table `ssmdemo`.`test` trx id 110687270 lock_mode X locks rec but not gap
    Record lock, heap no 6 PHYSICAL RECORD: n_fields 2; compact format; info bits 32
     0: len 13; hex 33736466736466736466736466; asc 3sdfsdfsdfsdf;;
     1: len 4; hex 01cba5c0; asc     ;;
    
    *** (2) WAITING FOR THIS LOCK TO BE GRANTED:
    RECORD LOCKS space id 79351 page no 4 n bits 80 index str of table `ssmdemo`.`test` trx id 110687270 lock_mode X waiting
    Record lock, heap no 2 PHYSICAL RECORD: n_fields 2; compact format; info bits 32
     0: len 30; hex 317364667364667364667364667364667364667364667364667364666c6b; asc 1sdfsdfsdfsdfsdfsdfsdfsdfsdflk; (total 46 bytes);
     1: len 4; hex 009c2ac7; asc   * ;;
    
    *** WE ROLL BACK TRANSACTION (2)

以上日志说明：

事务1正在执行【update test set str = “3333333” where str = ‘3sdfsdfsdfsdf’】语句，等待索引str=3sdfsdfsdfsdf上的锁，持有索引str = **1sdfsdfsdfsdfsdfsdfsdfsdfsdflkj;lkjlkhjs;lfgdg** 上的锁

事务2正在执行【update test set str = “111111111” where str = “1sdfsdfsdfsdfsdfsdfsdfsdfsdflkj;lkjlkhjs;lfgdg”】语句，持有索引str=3sdfsdfsdfsdf上的锁，等待索引str = **1sdfsdfsdfsdfsdfsdfsdfsdfsdflkj;lkjlkhjs;lfgdg** 上的锁。

**需要注意的是因“1sdfsdfsdfsdfsdfsdfsdfsdfsdflkj;lkjlkhjs;lfgdg”长度太长，asc 仅显示了前31位字符。**

# 间隙锁不互斥导致死锁 #

会话1和会话2连续执行：

mysql> begin;select * from test where str = '3abc' for update;               
    Query OK, 0 rows affected (0.00 sec)

会话1和会话2连续执行：

mysql> insert into test(str) value('3abc');

当会话2执行后立刻返回：

ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction

检测到死锁，死锁日志如下：

LATEST DETECTED DEADLOCK
    ------------------------
    2020-08-10 20:52:16 0x7fb726fa5700
    *** (1) TRANSACTION:
    TRANSACTION 110687354, ACTIVE 28 sec inserting
    mysql tables in use 1, locked 1
    LOCK WAIT 3 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 1
    MySQL thread id 347214, OS thread handle 140424592910080, query id 238864299 localhost root update
    insert into test(str) value('3abc')
    *** (1) WAITING FOR THIS LOCK TO BE GRANTED:
    RECORD LOCKS space id 79352 page no 4 n bits 80 index str of table `ssmdemo`.`test` trx id 110687354 lock_mode X locks gap before rec insert intention waiting
    Record lock, heap no 4 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
     0: len 13; hex 33736466736466736466736466; asc 3sdfsdfsdfsdf;;
     1: len 4; hex 01cba5c0; asc     ;;
    
    *** (2) TRANSACTION:
    TRANSACTION 110687353, ACTIVE 52 sec inserting
    mysql tables in use 1, locked 1
    3 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 1
    MySQL thread id 347255, OS thread handle 140424609683200, query id 238864300 localhost root update
    insert into test(str) value('3abc')
    *** (2) HOLDS THE LOCK(S):
    RECORD LOCKS space id 79352 page no 4 n bits 72 index str of table `ssmdemo`.`test` trx id 110687353 lock_mode X locks gap before rec
    Record lock, heap no 4 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
     0: len 13; hex 33736466736466736466736466; asc 3sdfsdfsdfsdf;;
     1: len 4; hex 01cba5c0; asc     ;;
    
    *** (2) WAITING FOR THIS LOCK TO BE GRANTED:
    RECORD LOCKS space id 79352 page no 4 n bits 80 index str of table `ssmdemo`.`test` trx id 110687353 lock_mode X locks gap before rec insert intention waiting
    Record lock, heap no 4 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
     0: len 13; hex 33736466736466736466736466; asc 3sdfsdfsdfsdf;;
     1: len 4; hex 01cba5c0; asc     ;;
    
    *** WE ROLL BACK TRANSACTION (2)

事务1：

等待索引 str=3sdfsdfsdfsdf 前的【 gap before rec 】间隙锁。

事务2：

持有索引 str=3sdfsdfsdfsdf 前的间隙锁。

等到索引 str=3sdfsdfsdfsdf 前的间隙锁。

说明两个会话都持有（2werwerwerwerwerwerweoijonsfoihdighoiusdhgpisud，3sdfsdfsdfsdf）的间隙锁，当执行插入时又互相等待对方的间隙锁，因此导致死锁。