如何阅读MySQL死锁日志

老叶茶馆

发布于 2022-12-02 19:20:42

1.8K0

发布于 2022-12-02 19:20:42

现象描述

客户在夜间批量执行数据处理时发生了死锁现象，是由不同的会话并发删除数据引起的，这个问题原因是比较简单，但想通过这个案例让大家熟悉如何去排查死锁问题，如何去阅读死锁日志这才是目的。通过模拟用户死锁现象后，死锁日志如下:

*** (1) TRANSACTION:
TRANSACTION 39474, ACTIVE 58 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1200, 4 row lock(s), undo log entries 3
MySQL thread id 9, OS thread handle 123145525800960, query id 77 localhost root updating
DELETE FROM t1 WHERE id = 4
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 114 page no 4 n bits 80 index PRIMARY of table `dhy`.`t1` trx id 39474 lock_mode X locks rec but not gap waiting
Record lock, heap no 5 PHYSICAL RECORD: n_fields 4; compact format; info bits 32
 0: len 4; hex 00000004; asc     ;;
 1: len 6; hex 000000009a33; asc      3;;
 2: len 7; hex 02000001471399; asc     G  ;;
 3: len 2; hex 6464; asc dd;;

*** (2) TRANSACTION:
TRANSACTION 39475, ACTIVE 46 sec starting index read
mysql tables in use 1, locked 1
3 lock struct(s), heap size 1200, 4 row lock(s), undo log entries 3
MySQL thread id 10, OS thread handle 123145526104064, query id 78 localhost root updating
DELETE FROM t1 WHERE id = 3
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 114 page no 4 n bits 80 index PRIMARY of table `dhy`.`t1` trx id 39475 lock_mode X locks rec but not gap
Record lock, heap no 5 PHYSICAL RECORD: n_fields 4; compact format; info bits 32
 0: len 4; hex 00000004; asc     ;;
 1: len 6; hex 000000009a33; asc      3;;
 2: len 7; hex 02000001471399; asc     G  ;;
 3: len 2; hex 6464; asc dd;;

Record lock, heap no 6 PHYSICAL RECORD: n_fields 4; compact format; info bits 32
 0: len 4; hex 00000005; asc     ;;
 1: len 6; hex 000000009a33; asc      3;;
 2: len 7; hex 02000001471375; asc     G u;;
 3: len 2; hex 6565; asc ee;;

Record lock, heap no 7 PHYSICAL RECORD: n_fields 4; compact format; info bits 32
 0: len 4; hex 00000006; asc     ;;
 1: len 6; hex 000000009a33; asc      3;;
 2: len 7; hex 02000001471351; asc     G Q;;
 3: len 2; hex 6666; asc ff;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 114 page no 4 n bits 80 index PRIMARY of table `dhy`.`t1` trx id 39475 lock_mode X locks rec but not gap waiting
Record lock, heap no 4 PHYSICAL RECORD: n_fields 4; compact format; info bits 32
 0: len 4; hex 00000003; asc     ;;
 1: len 6; hex 000000009a32; asc      2;;
 2: len 7; hex 01000001462e1f; asc     F. ;;
 3: len 2; hex 6363; asc cc;;

*** WE ROLL BACK TRANSACTION (2)

如何阅读死锁日志

要排查死锁问题我们就要学会如何查看死锁日志，但MySQL死锁日志看起来并不是很直观需要我们一步一步耐心分析。我们将上面的死锁日志拆分阅读，我们可以得出以下信息:

两个事务的事务ID TRANSACTION 39474 TRANSACTION 39475
事务39474在执行delete语句是发生了锁等待

DELETE FROM t1 WHERE id = 4
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 114 page no 4 n bits 80 index PRIMARY of table `dhy`.`t1` trx id 39474 lock_mode X locks rec but not gap waiting
Record lock, heap no 5 PHYSICAL RECORD: n_fields 4; compact format; info bits 32
 0: len 4; hex 00000004; asc     ;; //聚集索引的值
 1: len 6; hex 000000009a33; asc      3;; //事务ID
 2: len 7; hex 02000001471399; asc     G  ;; //undo 记录
 3: len 2; hex 6464; asc dd;; //非主键字段的值

通过以上信息可以得出事务39474执行delete语句时，锁等待发生在申请ID=4这条记录上的X锁“lock_mode X locks rec but not gap waiting”

事务39475持有锁的信息

*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 114 page no 4 n bits 80 index PRIMARY of table `dhy`.`t1` trx id 39475 lock_mode X locks rec but not gap
Record lock, heap no 5 PHYSICAL RECORD: n_fields 4; compact format; info bits 32
 0: len 4; hex 00000004; asc     ;;
 1: len 6; hex 000000009a33; asc      3;;
 2: len 7; hex 02000001471399; asc     G  ;;
 3: len 2; hex 6464; asc dd;;

Record lock, heap no 6 PHYSICAL RECORD: n_fields 4; compact format; info bits 32
 0: len 4; hex 00000005; asc     ;;
 1: len 6; hex 000000009a33; asc      3;;
 2: len 7; hex 02000001471375; asc     G u;;
 3: len 2; hex 6565; asc ee;;

Record lock, heap no 7 PHYSICAL RECORD: n_fields 4; compact format; info bits 32
 0: len 4; hex 00000006; asc     ;;
 1: len 6; hex 000000009a33; asc      3;;
 2: len 7; hex 02000001471351; asc     G Q;;
 3: len 2; hex 6666; asc ff;;

事务39475持有在ID=4，5，6上X锁

事务39475同样在执行delete语句时发生了所等待

*** (2) TRANSACTION:
TRANSACTION 39475, ACTIVE 46 sec starting index read
mysql tables in use 1, locked 1
3 lock struct(s), heap size 1200, 4 row lock(s), undo log entries 3
MySQL thread id 10, OS thread handle 123145526104064, query id 78 localhost root updating
DELETE FROM t1 WHERE id = 3

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 114 page no 4 n bits 80 index PRIMARY of table `dhy`.`t1` trx id 39475 lock_mode X locks rec but not gap waiting
Record lock, heap no 4 PHYSICAL RECORD: n_fields 4; compact format; info bits 32
 0: len 4; hex 00000003; asc     ;;
 1: len 6; hex 000000009a32; asc      2;;
 2: len 7; hex 01000001462e1f; asc     F. ;;
 3: len 2; hex 6363; asc cc;;

申请ID=3上的X锁时发生了所等待，执行的语句是:DELETE FROM t1 WHERE id = 3，那么可以得出39474在id=3上持有了X锁，但是在死锁日志中并没有显示出事务39474持有锁的信息那么这两个事务加锁的顺序应是: 1. 事务39474持有了id=3上的X锁 2. 事务39475持有了id=4上的X锁 3. 事务39474申请id=4上X锁时发生了锁等待执行的语句是:DELETE FROM t1 WHERE id = 4 4. 事务39475申请id=3上X锁时触发了死锁，因为此时双方都在申请对方持有的锁不能进行下去了。

事务2被回滚

*** WE ROLL BACK TRANSACTION (2)

事务39475持有ID = 4， 5， 6上的X锁是由哪个语句引起的，无法直观从死锁日志里看出。可以通过打开general日志或者binlog或者业务代码来查看整个事务逻辑

实验步骤及表结构

搭建可按实验步骤自己模拟测试，表结构及数据如下:

CREATE TABLE t1 (id int unsigned NOT NULL PRIMARY KEY, c1 
varchar(10));
INSERT INTO t1 VALUES (1, 'aa'), (2, 'bb'), (3, 'cc'), (4, 'dd'), (5, 'ee'), (6, 'ff');

操作步骤如表所示:

Session1	Session2
START TRANSACTION;DELETE FROM t1 WHERE id = 1;
	START TRANSACTION;DELETE FROM t1 WHERE id = 6;
DELETE FROM t1 WHERE id = 2;
	DELETE FROM t1 WHERE id = 5;
DELETE FROM t1 WHERE id = 3;
	DELETE FROM t1 WHERE id = 4;
DELETE FROM t1 WHERE id = 4;
	DELETE FROM t1 WHERE id = 3;//发生死锁