vlambda博客
学习文章列表

一次死锁的过程分析和MySQL8.0版本记录了更完整的死锁日志


目录

  1. 环境

  2. 表结构和数据的初始化

  3. 死锁日志分析

    3.1 当时的死锁日志类似下面的内容

    3.2 声明

    3.3 事务一的信息

    3.4 事务二的信息

    3.5 根据死锁信息分析出的两个事务的加锁规则和死锁成因

  4. 根据上面的死锁日志分析和业务逻辑复现该死锁是如何形成的

  5. 解决本案例死锁的办法之一

  6. MySQL 8.0.19 版本测试本案例

  7. 小结

1. 环境

事务隔离级别为RC读已提交 MySQL版本为 5.7.26 先介绍一下数据表情况,因为涉及到公司内部真实的数据,所以以下都做了模拟,但不会影响具体的分析。

2. 表结构和数据的初始化

 
   
   
 
  1. CREATE TABLE `t1` (

  2. `ID` int(10) unsigned NOT NULL AUTO_INCREMENT COMMENT '自增ID',

  3. `t1` int(10) NOT NULL COMMENT '',

  4. `t2` int(10) NOT NULL COMMENT '',

  5. `order_no` varchar(64) NOT NULL DEFAULT '' COMMENT 'order no',

  6. `status` int(10) NOT NULL COMMENT '状态',

  7. `createtime` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP COMMENT '发生时间',

  8. PRIMARY KEY (`ID`),

  9. KEY `idx_order_no` (`order_no`),

  10. KEY `idx_status_createtime` (`status`, `createtime`)

  11. ) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COMMENT='';



  12. 表中有3个索引,其中一个主键索引,两个辅助索引。

  13. 插入一行记录

  14. INSERT INTO `t1` (`ID`, `t1`, `t2`, `order_no`, `status`, `createtime`) VALUES ('1', '1', '1', '123456', '0', '2020-04-24 12:10:00');



  15. mysql> select ID,order_no, status, createtime from t1 where order_no='123456';

  16. +---------+-------------------+---------------------+

  17. | ID | order_no | status | createtime |

  18. +---------+-------------------+---------------------+

  19. | 1 | 123456 | 0 | 2020-04-24 12:10:00 |

  20. +---------+-------------------+---------------------+

  21. 1 row in set (0.00 sec)

3. 死锁日志分析

3.1 当时的死锁日志类似下面的内容

 
   
   
 
  1. 2020-04-24T12:18:06.804155+08:00 4106 [Note] InnoDB: Transactions deadlock detected, dumping detailed information.

  2. 2020-04-24T12:18:06.804185+08:00 4106 [Note] InnoDB:

  3. *** (1) TRANSACTION:


  4. TRANSACTION 18912896, ACTIVE 3 sec starting index read

  5. mysql tables in use 1, locked 1

  6. LOCK WAIT 3 lock struct(s), heap size 1136, 2 row lock(s)

  7. MySQL thread id 4108, OS thread handle 140149994698496, query id 31983724 localhost root Searching rows for update

  8. UPDATE t1 SET status = 5 WHERE status = 0 AND (`createtime` BETWEEN DATE_SUB(NOW(),INTERVAL 90 MINUTE) AND DATE_SUB(NOW(),INTERVAL 60 MINUTE))

  9. 2020-04-24T12:18:06.804257+08:00 4106 [Note] InnoDB: *** (1) WAITING FOR THIS LOCK TO BE GRANTED:


  10. RECORD LOCKS space id 260 page no 3 n bits 72 index PRIMARY of table `sbtest`.`t1` trx id 18912896 lock_mode X locks rec but not gap waiting

  11. Record lock, heap no 2 PHYSICAL RECORD: n_fields 8; compact format; info bits 0

  12. 0: len 4; hex 00000001; asc ;;

  13. 1: len 6; hex 000001209381; asc ;;

  14. 2: len 7; hex 45000001d825b8; asc E % ;;

  15. 3: len 4; hex 80000001; asc ;;

  16. 4: len 4; hex 80000001; asc ;;

  17. 5: len 6; hex 313233343536; asc 123456;;

  18. 6: len 4; hex 80000001; asc ;;

  19. 7: len 4; hex 5ea26698; asc ^ f ;;


  20. 2020-04-24T12:18:06.805410+08:00 4106 [Note] InnoDB: *** (2) TRANSACTION:


  21. TRANSACTION 18912129, ACTIVE 42 sec updating or deleting

  22. mysql tables in use 1, locked 1

  23. 4 lock struct(s), heap size 1136, 3 row lock(s), undo log entries 1

  24. MySQL thread id 4106, OS thread handle 140149998397184, query id 31985074 localhost root updating

  25. update t1 set status=1 where order_no='123456'

  26. 2020-04-24T12:18:06.805467+08:00 4106 [Note] InnoDB: *** (2) HOLDS THE LOCK(S):


  27. RECORD LOCKS space id 260 page no 3 n bits 72 index PRIMARY of table `sbtest`.`t1` trx id 18912129 lock_mode X locks rec but not gap

  28. Record lock, heap no 2 PHYSICAL RECORD: n_fields 8; compact format; info bits 0

  29. 0: len 4; hex 00000001; asc ;;

  30. 1: len 6; hex 000001209381; asc ;;

  31. 2: len 7; hex 45000001d825b8; asc E % ;;

  32. 3: len 4; hex 80000001; asc ;;

  33. 4: len 4; hex 80000001; asc ;;

  34. 5: len 6; hex 313233343536; asc 123456;;

  35. 6: len 4; hex 80000001; asc ;;

  36. 7: len 4; hex 5ea26698; asc ^ f ;;


  37. 2020-04-24T12:18:06.805835+08:00 4106 [Note] InnoDB: *** (2) WAITING FOR THIS LOCK TO BE GRANTED:


  38. RECORD LOCKS space id 260 page no 5 n bits 72 index idx_status_createtime of table `sbtest`.`t1` trx id 18912129 lock_mode X locks rec but not gap waiting

  39. Record lock, heap no 2 PHYSICAL RECORD: n_fields 3; compact format; info bits 0

  40. 0: len 4; hex 80000000; asc ;;

  41. 1: len 4; hex 5ea26698; asc ^ f ;;

  42. 2: len 4; hex 00000001; asc ;;


  43. 2020-04-24T12:18:06.806005+08:00 4106 [Note] InnoDB: *** WE ROLL BACK TRANSACTION (1)

3.2 声明:死锁日志中的TRANSACTION 18912129 记为 事务一 死锁日志中的TRANSACTION 18912896 记为 事务二 分析死锁的时候,我习惯把事务编号小的定义为事务一

3.3 事务一的信息:

 
   
   
 
  1. 事务一的SQL语句:

  2. update t1 set status=1 where order_no='123456'


  3. 持有的锁信息:

  4. HOLDS THE LOCK(S) --用来表示这个事务持有哪些锁

  5. index PRIMARY of table `sbtest`.`t1` --表示加锁是在加在表t1 的索引PRIMARY

  6. n_fields 8: --表示这个记录是8

  7. 0: len 4; hex 00000001; asc ;; --是第一个字段,也就是主键字段 ID, 116进制转换为10进制, 得到的值为1


  8. 所以事务一持有的锁: PRIMARY: record lock: [1]


  9. 在等待的锁信息:

  10. index idx_status_createtime of table `sbtest`.`t1` --表示在等的是表t1 的辅助索引idx_status_createtime 上面的锁

  11. lock_mode X locks rec but not gap waiting --表示需要加一个排他锁(写锁),当前的状态是等待中

  12. Record lock --表示这是一个记录锁

  13. n_fields 3 --表示辅助索引idx_status_createtime的记录是3列, 根据索引的存储结构, 3列依次为 statuscreatetimeID

  14. 0: len 4; hex 80000000; asc ;; --status字段, 值为 0

  15. 1: len 4; hex 5ea26698; asc ^ f ;; --createtime字段, 5ea26698 16进制转换为10进制, 得到时间戳1587701400, 转换为具体的日期: 2020-04-24 12:10:00

  16. 2: len 4; hex 00000001; asc ;; --ID字段, 116进制转换为10进制, 得到的值为1


  17. 所以在等待事务二 辅助索引idx_status_createtime (status=0,createtime='2020-04-24 12:10:00',ID=1) 这一行的记录锁

3.4 事务二的信息

 
   
   
 
  1. 事务二的SQL语句

  2. UPDATE t1 SET status = 5 WHERE status = 0 AND (`createtime` BETWEEN DATE_SUB(NOW(),INTERVAL 90 MINUTE) AND DATE_SUB(NOW(),INTERVAL 60 MINUTE));


  3. 持有的锁信息

  4. 根据事务一在等待事务二上表t1辅助索引idx_nStatus_CreateTime 上的行锁,所以推导出事务二持有表t1辅助索引idx_nStatus_CreateTime 上的行锁

  5. 所以事务二持有的锁: idx_status_createtime: record lock: (status=0,createtime='2020-04-24 12:10:00',ID=1)


  6. 在等待的锁信息

  7. index PRIMARY of table `sbtest`.`t1` --表示在等的是表t1 的主键索引 上面的锁

  8. lock_mode X locks rec but not gap waiting --表示需要加一个排他锁(写锁),当前的状态是等待中

  9. Record lock --是一个记录锁

  10. 0: len 4; hex 00000001; asc ;; --是第一个字段,也就是主键字段 ID, 值为 1


  11. 所以在等待事务一的: PRIMARY: record lock:(ID=1)

3.5 根据死锁信息分析出的两个事务的加锁规则和死锁成因

时间点 事务一 事务二
T1
持有主键索引 ID=1 的记录锁, 锁的模式为排他锁
T2
持有辅助索引:
idx_status_createtime: record lock: status=0,createtime='2020-04-24 12:10:00', ID=1) 的记录锁,锁的模式为排他锁
T3
 在等主键索引 ID=1 的记录锁 
T4 在等辅助索引idx_status_createtime: 
   record lock: (status=0, createtime='2020-04-24 12:10:00',ID=1)的记录锁

T3被T1阻塞,T4被T2阻塞,因此锁资源请求形成了环路,进而触发死锁检测, 因此导致了死锁。

4. 根据上面的死锁分析和业务逻辑复现该死锁

时间点 事务一 事务二

begin; 
select status from t1 where 

 order_no='123456' for update; 

T1 持有主键索引 ID=1 的记录锁, 锁的模式为排他锁



UPDATE t1 SET status = 5 WHERE status = 0 AND (createtime BETWEEN DATE_SUB(NOW(),INTERVAL 90 MINUTE)  AND DATE_SUB(NOW(),INTERVAL 60 MINUTE));
T2
持有辅助索引:
idx_status_createtime: (record lock: status=0, createtime='2020-04-24 12:10:00', ID=1) 的记录锁,锁的模式为排他锁
T3
 在等主键索引 ID=1 的记录锁 

update t1 set status=1 where order_no='123456';
T4 在等辅助索引idx_status_createtime: 
   record lock: (status=0, createtime='2020-04-24 12:10:00',ID=1)的记录锁

T3被T1阻塞,T4被T2阻塞,因此锁资源请求形成了环路,进而触发死锁检测, MySQL会把执行代价最小的事务回滚掉,让其它事务得以继续进行。 

查看 informationschema 下的两个视图 innodblocks 和 innodblockwaits 确认T1、T2、T3时刻持有的锁和在等待的锁的详情

 
   
   
 
  1. mysql> select * from information_schema.innodb_locks\G

  2. *************************** 1. row ***************************

  3. lock_id: 18912896:260:3:2 --请求的锁

  4. lock_trx_id: 18912896 --被阻塞的事务ID

  5. lock_mode: X --排他锁

  6. lock_type: RECORD --锁类型 记录锁

  7. lock_table: `sbtest`.`t1` --表

  8. lock_index: PRIMARY --索引为主键索引

  9. lock_space: 260

  10. lock_page: 3

  11. lock_rec: 2

  12. lock_data: 1 --请求加锁的row dataID=1这行记录

  13. *************************** 2. row ***************************

  14. lock_id: 18912129:260:3:2 --持有的锁

  15. lock_trx_id: 18912129 --持有锁的事务ID

  16. lock_mode: X --排他锁 LOCK_X

  17. lock_type: RECORD --锁类型 记录锁

  18. lock_table: `sbtest`.`t1` --表

  19. lock_index: PRIMARY --索引为主键索引

  20. lock_space: 260 --table space id

  21. lock_page: 3 --page no

  22. lock_rec: 2 --heap no

  23. lock_data: 1 --被加锁的row dataID=1这行记录

  24. 2 rows in set (0.00 sec)

trxid 为 18912129 向表 t1 加了一个 X 的记录锁, trxid 为 18912896 的事务向表 t1 申请了一个 X 的记录锁,lock_data 的值为1 即记录的主键值为1,申请了相同的资源,因此这里会有等待。

事务二更新语句的WHERE条件查询到的记录是为空的, 但是为什么会持有辅助索引idxstatuscreatetime上面的锁呢?

 
   
   
 
  1. mysql> select * from t1 WHERE status = 0 AND (`createtime` BETWEEN DATE_SUB(NOW(),INTERVAL 90 MINUTE) AND DATE_SUB(NOW(),INTERVAL 60 MINUTE));

  2. Empty set (0.00 sec)

原因:因为这里是辅助索引的范围查询更新,范围查询就会往后查找,刚好找到 (status=0,createtime='2020-04-24 12:10:00')的记录才会停下来, 因此持有行锁:(status=0,createtime='2020-04-24 12:10:00',ID=1)

MySQL8.0 版本informationschema中的innodblocks和innodblockwaits表被移除,取而代之的是performanceschema中的datalocks和datalockwaits表,通过 data_locks 可以看到数据加锁的详情。同时,下文会把这个案例在 MySQL 8.0.19 下做测试, 因为 MySQL 8.0记录了更详细的死锁日志,分析死锁会更加轻松。

 
   
   
 
  1. mysql> select * from information_schema.innodb_lock_waits\G;

  2. *************************** 1. row ***************************

  3. requesting_trx_id: 18912896 --请求锁资源的事务ID

  4. requested_lock_id: 18912896:260:3:2 --申请的锁的ID

  5. blocking_trx_id: 18912129 --持有锁的事务ID

  6. blocking_lock_id: 18912129:260:3:2 --持有的锁的ID

5. 解决本案例死锁的办法之一

经过跟相关的开发人员沟通, 事务一的 UPDATE语句可以不放在显示声明的事务内执行, 然后把更新语句移出显示声明的事务中就可以避免本案例的死锁。

6. MySQL 8.0.19 版本测试本案例

环境

 
   
   
 
  1. mysql> select version();

  2. +-----------+

  3. | version() |

  4. +-----------+

  5. | 8.0.19 |

  6. +-----------+

  7. 1 row in set (0.00 sec)


  8. mysql> select @@session.transaction_isolation;

  9. +---------------------------------+

  10. | @@session.transaction_isolation |

  11. +---------------------------------+

  12. | READ-COMMITTED |

  13. +---------------------------------+

  14. 1 row in set (0.00 sec)

事务的执行顺序

时间点 事务一 事务二
T1 begin; 
select status from t1 where 

 order_no='123456' for update; 

T2
UPDATE t1 SET status = 5 WHERE status = 0 AND (`createtime` BETWEEN DATE_SUB(NOW(),INTERVAL 90 MINUTE)  AND DATE_SUB(NOW(),INTERVAL 60 MINUTE));
T3 update t1 set status=1 where order_no='123456';

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

查看 informationschema.innodblocks 确认T1、T2 时刻持有的锁和在等待的锁的详情

 
   
   
 
  1. mysql> select ENGINE_LOCK_ID,ENGINE_TRANSACTION_ID,THREAD_ID,OBJECT_NAME,INDEX_NAME,LOCK_TYPE,LOCK_MODE,LOCK_STATUS,LOCK_DATA from performance_schema.data_locks;

  2. +----------------------------------------+-----------------------+-----------+-------------+-----------------------+-----------+---------------+-------------+------------------+

  3. | ENGINE_LOCK_ID | ENGINE_TRANSACTION_ID | THREAD_ID | OBJECT_NAME | INDEX_NAME | LOCK_TYPE | LOCK_MODE | LOCK_STATUS | LOCK_DATA |

  4. +----------------------------------------+-----------------------+-----------+-------------+-----------------------+-----------+---------------+-------------+------------------+

  5. | 140472041388912:1072:140471938672632 | 212055 | 30483 | t1 | NULL | TABLE | IX | GRANTED | NULL |

  6. | 140472041388912:15:6:2:140471938669688 | 212055 | 30483 | t1 | idx_status_createtime | RECORD | X,REC_NOT_GAP | GRANTED | 0, 0x5EA26698, 1 |

  7. | 140472041388912:15:4:2:140471938670032 | 212055 | 30483 | t1 | PRIMARY | RECORD | X,REC_NOT_GAP | WAITING | 1 |

  8. | 140472041388040:1072:140471938666488 | 212052 | 30481 | t1 | NULL | TABLE | IX | GRANTED | NULL |

  9. | 140472041388040:15:5:2:140471938663448 | 212052 | 30481 | t1 | idx_order_no | RECORD | X,REC_NOT_GAP | GRANTED | '123456', 1 |

  10. | 140472041388040:15:4:2:140471938663792 | 212052 | 30481 | t1 | PRIMARY | RECORD | X,REC_NOT_GAP | GRANTED | 1 |

  11. +----------------------------------------+-----------------------+-----------+-------------+-----------------------+-----------+---------------+-------------+------------------+

  12. 6 rows in set (0.00 sec)

事务一在T1时刻持有的锁:INDEXNAME=PRIMARY,LOCKTYPE=RECORD,LOCKSTATUS=GRANTED,LOCKDATA=1 : PRIMARY:recordlock:[1]INDEXNAME=idxorderno,LOCKTYPE=RECORD,LOCKSTATUS=GRANTED,LOCKDATA='123456', 1 : idx_order_no:recordlock:(order='123456',ID=1)事务二持有的锁:INDEXNAME=idxstatuscreatetime ,LOCKTYPE=RECORD,LOCKSTATUS=GRANTED,LOCKDATA='0, 0x5EA26698, 1': (status=0,createtime='2020-04-24 12:10:00',ID=1)事务二在等待的锁:INDEXNAME=PRIMARY,LOCKTYPE=RECORD,LOCKSTATUS=WAITING, LOCKDATA=1 表示 事务二在等的锁为: PRIMARY:recordlock:[1]

死锁日志

 
   
   
 
  1. 2020-04-24 12:15:36 0x7fc1947ea700

  2. *** (1) TRANSACTION:

  3. TRANSACTION 212055, ACTIVE 1 sec starting index read

  4. mysql tables in use 1, locked 1

  5. LOCK WAIT 3 lock struct(s), heap size 1136, 2 row lock(s)

  6. MySQL thread id 30432, OS thread handle 140468864067328, query id 135057 localhost root Searching rows for update

  7. UPDATE t1 SET status = 5 WHERE status = 0 AND (`createtime` BETWEEN DATE_SUB(NOW(),INTERVAL 90 MINUTE) AND DATE_SUB(NOW(),INTERVAL 60 MINUTE))


  8. *** (1) HOLDS THE LOCK(S): --持有的锁

  9. RECORD LOCKS space id 15 page no 6 n bits 72 index idx_status_createtime of table `sbtest`.`t1` trx id 212055 lock_mode X locks rec but not gap

  10. Record lock, heap no 2 PHYSICAL RECORD: n_fields 3; compact format; info bits 0

  11. 0: len 4; hex 80000000; asc ;;

  12. 1: len 4; hex 5ea26698; asc ^ f ;;

  13. 2: len 4; hex 00000001; asc ;;


  14. *** (1) WAITING FOR THIS LOCK TO BE GRANTED: --在等待的锁

  15. RECORD LOCKS space id 15 page no 4 n bits 72 index PRIMARY of table `sbtest`.`t1` trx id 212055 lock_mode X locks rec but not gap waiting

  16. Record lock, heap no 2 PHYSICAL RECORD: n_fields 8; compact format; info bits 0

  17. 0: len 4; hex 00000001; asc ;;

  18. 1: len 6; hex 000000033c54; asc <T;;

  19. 2: len 7; hex 0200000ff80e6a; asc j;;

  20. 3: len 4; hex 80000001; asc ;;

  21. 4: len 4; hex 80000001; asc ;;

  22. 5: len 6; hex 313233343536; asc 123456;;

  23. 6: len 4; hex 80000001; asc ;;

  24. 7: len 4; hex 5ea26698; asc ^ f ;;


  25. *** (2) TRANSACTION:

  26. TRANSACTION 212052, ACTIVE 68 sec updating or deleting

  27. mysql tables in use 1, locked 1

  28. LOCK WAIT 4 lock struct(s), heap size 1136, 3 row lock(s), undo log entries 1

  29. MySQL thread id 30430, OS thread handle 140468857743104, query id 135061 localhost root updating

  30. update t1 set status=1 where order_no='123456'


  31. *** (2) HOLDS THE LOCK(S): --持有的锁

  32. RECORD LOCKS space id 15 page no 4 n bits 72 index PRIMARY of table `sbtest`.`t1` trx id 212052 lock_mode X locks rec but not gap

  33. Record lock, heap no 2 PHYSICAL RECORD: n_fields 8; compact format; info bits 0

  34. 0: len 4; hex 00000001; asc ;;

  35. 1: len 6; hex 000000033c54; asc <T;;

  36. 2: len 7; hex 0200000ff80e6a; asc j;;

  37. 3: len 4; hex 80000001; asc ;;

  38. 4: len 4; hex 80000001; asc ;;

  39. 5: len 6; hex 313233343536; asc 123456;;

  40. 6: len 4; hex 80000001; asc ;;

  41. 7: len 4; hex 5ea26698; asc ^ f ;;


  42. *** (2) WAITING FOR THIS LOCK TO BE GRANTED: --在等待的锁

  43. RECORD LOCKS space id 15 page no 6 n bits 72 index idx_status_createtime of table `sbtest`.`t1` trx id 212052 lock_mode X locks rec but not gap waiting

  44. Record lock, heap no 2 PHYSICAL RECORD: n_fields 3; compact format; info bits 0

  45. 0: len 4; hex 80000000; asc ;;

  46. 1: len 4; hex 5ea26698; asc ^ f ;;

  47. 2: len 4; hex 00000001; asc ;;


  48. *** WE ROLL BACK TRANSACTION (1)

可以看到, MySQL 8.0版本的死锁日志更加完整了:把事务持有的锁和在等待的锁的详情都记录下来了。

7. 小结

死锁一般可以结合死锁日志、加锁规则和业务场景来做相关的分析 辅助索引的范围查询更新加锁,需要往后找到一条满足条件的记录才会停止扫描 加锁是在加在索引上的,当表中有多个索引,只会对必要的索引加锁,例如本案例中的表t1有3个索引,分别为 PRIMARY KEY、idxorderno和idxstatuscreatetime,当执行 select * from t1 where orderno='123456' for update; 语句后,会对索引 PRIMARY KEY、idxorderno 的记录进行加锁,并不会对索引 idxstatuscreatetime 的记录进行加锁。MySQL 8.0版本通过 performanceschema.data_locks 可以看到事务持有的锁列表和在等待的锁的列表。同时,MySQL 8.0版本记录的死锁日志更加完整了,不再需要根据死锁日志中的锁等待的记录信息推导出另一个事务持有的锁信息,分析死锁会更加轻松。



知数堂精品课程,MySQL实战/优化、SQL优化、Python运维与开发、Elastic现已发车。课程已全面升级到MySQL 8.0版本,现在上车刚刚好,一起开启MySQL 8.0的修行之旅吧

加入知数堂

挑战50万+年薪!



扫码入群了解课程详情吧,助教妹子在等哟