MySQL一次死锁排查过程分析（双update）

1.环境

MySQL5.7.26，事务隔离级别为RR

2.表结构

+------------------+------------------+------+-----+---------------------+----------------+
| Field            | Type             | Null | Key | Default             | Extra          |
+------------------+------------------+------+-----+---------------------+----------------+
| id               | int(11) unsigned | NO   | PRI | NULL                | auto_increment |
| config_id        | int(11)          | NO   |     | NULL                |                |
| place_code       | varchar(16)      | NO   |     |                     |                |
| stock_date       | date             | NO   |     | NULL                |                |
| start_time       | time             | NO   |     | NULL                |                |
| end_time         | time             | NO   |     | NULL                |                |
| a_amount         | int(11)          | NO   |     | 0                   |                |
| t_amount         | int(11)          | NO   |     | 0                   |                |
| show_apps        | varchar(512)     | YES  |     | NULL                |                |
| update_time      | timestamp        | YES  |     | NULL                |                |
| create_time      | timestamp        | NO   |     | 0000-00-00 00:00:00 |                |
+------------------+------------------+------+-----+---------------------+----------------+

3.死锁日志分析

3.1 死锁日志如下

2020-07-07T23:36:18.057866Z 2210220 [Note] InnoDB: Transactions deadlock detected, dumping detailed information.
2020-07-07T23:36:18.057932Z 2210220 [Note] InnoDB: 
*** (1) TRANSACTION:

TRANSACTION 182336318, ACTIVE 1 sec fetching rows
mysql tables in use 1, locked 1
LOCK WAIT 133 lock struct(s), heap size 24784, 32399 row lock(s), undo log entries 1
MySQL thread id 2210217, OS thread handle 139920667432704, query id 420859658 10.11.100.12 tc updating
UPDATE c_place_time_stock SET a_amount=(c_place_time_stock.a_amount - 2), update_time=now() WHERE c_place_time_stock.place_code = 'A02' AND c_place_time_stock.stock_date = '2020-07-08' AND c_place_time_stock.start_time <= '08:00:00' AND c_place_time_stock.end_time > '08:00:00'
2020-07-07T23:36:18.058022Z 2210220 [Note] InnoDB: *** (1) WAITING FOR THIS LOCK TO BE GRANTED:

RECORD LOCKS space id 207 page no 239 n bits 344 index PRIMARY of table `tcenter`.`c_place_time_stock` trx id 182336318 lock_mode X waiting
Record lock, heap no 228 PHYSICAL RECORD: n_fields 13; compact format; info bits 0
 0: len 4; hex 0000a188; asc     ;;
 1: len 6; hex 00000ade3b3d; asc     ;=;;
 2: len 7; hex 76000018b80612; asc v      ;;
 3: len 4; hex 800002b4; asc     ;;
 4: len 3; hex 413237; asc A27;;
 5: len 3; hex 8fc8e8; asc    ;;
 6: len 3; hex 808780; asc    ;;
 7: len 3; hex 80f780; asc    ;;
 8: len 4; hex 800026b0; asc   & ;;
 9: len 4; hex 80002710; asc   ' ;;
 10: len 30; hex 3631303136332c3630303031362c3631303136382c3634303036382c3631; asc 610163,600016,610168,640068,61; (total 48 bytes);
 11: len 4; hex 5f0506f1; asc _   ;;
 12: len 4; hex 5efe174a; asc ^  J;;

2020-07-07T23:36:18.059281Z 2210220 [Note] InnoDB: *** (2) TRANSACTION:

TRANSACTION 182336317, ACTIVE 1 sec starting index read
mysql tables in use 1, locked 1
9 lock struct(s), heap size 1136, 28 row lock(s), undo log entries 16
MySQL thread id 2210220, OS thread handle 139920666892032, query id 420859667 10.11.100.12 tc updating
UPDATE c_place_time_stock SET a_amount=2168, update_time=now() WHERE c_place_time_stock.id = 41334
2020-07-07T23:36:18.059373Z 2210220 [Note] InnoDB: *** (2) HOLDS THE LOCK(S):

RECORD LOCKS space id 207 page no 239 n bits 344 index PRIMARY of table `tcenter`.`c_place_time_stock` trx id 182336317 lock_mode X locks rec but not gap
Record lock, heap no 228 PHYSICAL RECORD: n_fields 13; compact format; info bits 0
 0: len 4; hex 0000a188; asc     ;;
 1: len 6; hex 00000ade3b3d; asc     ;=;;
 2: len 7; hex 76000018b80612; asc v      ;;
 3: len 4; hex 800002b4; asc     ;;
 4: len 3; hex 413237; asc A27;;
 5: len 3; hex 8fc8e8; asc    ;;
 6: len 3; hex 808780; asc    ;;
 7: len 3; hex 80f780; asc    ;;
 8: len 4; hex 800026b0; asc   & ;;
 9: len 4; hex 80002710; asc   ' ;;
 10: len 30; hex 3631303136332c3630303031362c3631303136382c3634303036382c3631; asc 610163,600016,610168,640068,61; (total 48 bytes);
 11: len 4; hex 5f0506f1; asc _   ;;
 12: len 4; hex 5efe174a; asc ^  J;;

2020-07-07T23:36:18.060674Z 2210220 [Note] InnoDB: *** (2) WAITING FOR THIS LOCK TO BE GRANTED:

RECORD LOCKS space id 207 page no 239 n bits 344 index PRIMARY of table `tcenter`.`c_place_time_stock` trx id 182336317 lock_mode X locks rec but not gap waiting
Record lock, heap no 214 PHYSICAL RECORD: n_fields 13; compact format; info bits 0
 0: len 4; hex 0000a176; asc    v;;
 1: len 6; hex 00000ade3afa; asc     : ;;
 2: len 7; hex 50000017711ef0; asc P   q  ;;
 3: len 4; hex 80000257; asc    W;;
 4: len 3; hex 413031; asc A01;;
 5: len 3; hex 8fc8e8; asc    ;;
 6: len 3; hex 80d780; asc    ;;
 7: len 3; hex 80e780; asc    ;;
 8: len 4; hex 80000877; asc    w;;
 9: len 4; hex 80000823; asc    #;;
 10: len 30; hex 3631303136332c3630303031362c3631303136382c3634303036382c3631; asc 610163,600016,610168,640068,61; (total 62 bytes);
 11: len 4; hex 5f0506d5; asc _   ;;
 12: len 4; hex 5efe1749; asc ^  I;;

2020-07-07T23:36:18.061845Z 2210220 [Note] InnoDB: *** WE ROLL BACK TRANSACTION (2)

3.2 事务分析：将编号小的视为事务一（TRANSACTION 182336317）；编号大的视为事务二（TRANSACTION 182336318）

事务一的信息

事务一的SQL语句：
        UPDATE c_place_time_stock SET a_amount=2168, update_time=now() WHERE c_place_time_stock.id = 41334

持有的锁信息（InnoDB: *** (2) HOLDS THE LOCK(S):）
        --表示持有哪些锁，相关信息展示在下边
        index PRIMARY of table `tcenter`.`c_place_time_stock`  --表示锁是加在表c_place_time_stock的索引PRIMARY上
        lock_mode X locks    --表示锁的类型为X排他锁
        n_fields 13;    --表示这个记录是13列
        0: len 4; hex 0000a188; asc     ;;     --第一个字段，也就是主键字段ID，从十六进制转换为10进制，得到的值为41352，可知该事务持有的行锁的行ID为41352 
        ......
        每行均可通过进制转换得到对应的值
　　　　RECORD LOCKS space id 207 page no 239 n bits 344 index PRIMARY of table `tcenter`.`c_place_time_stock` trx id 182336317 lock_mode X locks rec but not gap waiting
　　　　Record lock, heap no 214 PHYSICAL RECORD: n_fields 13; compact format; info bits 0
　　　　　　--结合起来表示在主键上的page num=239上已经持有一个X锁(not gap waiting)，ID=41352

        结合前边的28 row lock(s)  ，可以知道现有28行记录锁      
    
在等待的锁信息（InnoDB: *** (2) WAITING FOR THIS LOCK TO BE GRANTED:）
　　　　  --表示等待锁的信息展示在下边
        index PRIMARY of table `tcenter`.`c_place_time_stock`    --表示在等待的是表c_place_time_stock的索引PRIMARY上面的锁
        lock_mode X locks rec but not gap waiting    --表示需要加一个排他锁（写锁），当前的状态是等待中
        Record lock    --表示这是一个记录行锁
        n_fields 13    --表示索引PRIMYRAY的记录是13列， 根据表的结构，依次为id、config_id、place_code ......
        0: len 4; hex 0000a176; asc    v;;    --进制转换后得到id值为41334，可知该事务等待在主键上加一个ID=41334的X锁（语句可以通过开启genaral日志获取） ...... 

所以在等待事务二的：PRIMARY: record lock: (id=41334）

 事务二的信息

事务二的SQL语句
 
UPDATE c_place_time_stock SET a_amount=(c_place_time_stock.a_amount - 2), update_time=now() WHERE c_place_time_stock.place_code = 'A02' AND c_place_time_stock.stock_date = '2020-07-08' AND c_place_time_stock.start_time <= '08:00:00' AND c_place_time_stock.end_time > '08:00:00'
  
持有的锁信息
      根据事务一在等待事务二上表c_place_time_stock的PRIMARY上的锁，且ID=41334，所以推导出事务二持有表c_place_time_stock 上PRIMARY的锁
 
 所以事务二正在申请持有(ID=41334)的X锁: PRIMAEY : record lock: (ID=41334)
 
 
 在等待的锁信息（InnoDB: *** (1) WAITING FOR THIS LOCK TO BE GRANTED:）
 
      index PRIMARY of table `sbtest`.`t1` --表示在等的是表t1 的主键索引 上面的锁
      lock_mode X locks rec but not gap waiting --表示需要加一个排他锁（写锁），当前的状态是等待中
      Record lock --是一个记录锁
 
      0: len 4; hex 0000a188; asc     ;; --是第一个字段，也就是主键字段 ID, 值为41352
      ......(13条记录与事务一持有锁描述相同)
      所以在事务二在等待事务一的: PRIMARY: record lock：(ID=41352) 。    

3.2 加锁规则和死锁成因

时间点	事务一	事务二
T1	持有主键索引ID=41352的记录锁，模式为排他锁
T2		申请主键为ID=41334的记录锁，模式为排他锁
T3		在等待主键索引ID=41352的记录锁
T4	申请并等待主键索引为ID=41334的记录锁
T3被T1阻塞，T4被T2阻塞

业务逻辑：

时间点	事务一	事务二
	查阅general_log，可以发现在事务一的业务逻辑中，有多个UPDATE，每个都是先select出ID，然后运算后进行UPDATE，在多个UPDATE完成后统一commit；先执行的update如下： UPDATE c_place_time_stock SET a_amount=9902, update_time=now() WHERE c_place_time_stock.id = 41352
T1	持有主键索引ID=41352的X锁
		UPDATE c_place_time_stock SET a_amount=(c_place_time_stock.a_amount - 2), update_time=now() WHERE c_place_time_stock.place_code = 'A02' AND c_place_time_stock.stock_date = '2020-07-08' AND c_place_time_stock.start_time <= '08:00:00' AND c_place_time_stock.end_time > '08:00:00'
T2		申请范围包括ID=41334和41352的记录锁，模式为排他锁
T3		等待主键索引ID=41352的记录锁释放,进入等待队列
	UPDATE c_place_time_stock SET a_amount=2168, update_time=now() WHERE c_place_time_stock.id = 41334
T4	本身持有主键索引ID=41352的X锁，改为申请ID=41334的X锁，进入等待队列，等待T3的释放申请。
T3被T1阻塞，T4被T3阻塞，同时T4所在事务未完成，无法释放T1，行程死锁环路。最终回归了代价最小的事务一

 4.解决方式

事务一的逻辑中每次update均commit;

5. 日志说明

锁的几种属性

LOCK_REC_NOT_GAP        （锁记录）
LOCK_GAP                         （锁记录前的GAP）
LOCK_ORDINARY              （同时锁记录+记录前的GAP ，也就是Next Key锁）
LOCK_INSERT_INTENTION（插入意向锁，其实是特殊的GAP锁）

锁的属性可以与锁模式任意组合

lock->type_mode       可以是Lock_X 或者Lock_S 
locks gap before rec  表示为gap锁：lock->type_mode & LOCK_GAP
locks rec but not gap 表示为记录锁，非gap锁：lock->type_mode & LOCK_REC_NOT_GAP
insert intention           表示为插入意向锁：lock->type_mode & LOCK_INSERT_INTENTION
waiting                       表示锁等待：lock->type_mode & LOCK_WAIT

参考1：https://mp.weixin.qq.com/s?__biz=MzI4NjExMDA4NQ==&mid=2648450273&idx=1&sn=2836db9eb1086a9fca91748dd233a234&chksm=f3c97c0bc4bef51d6c92e9a79b959c7f7e41367d5429ec80b5881d165978f311a4d8f0452634&scene=21#wechat_redirect

参考2：https://cloud.tencent.com/developer/article/1650865