Mysql死锁分析案例
Posted chenshouchang
tags:
篇首语：本文由小常识网(cha138.com)小编为大家整理，主要介绍了Mysql死锁分析案例相关的知识，希望对你有一定的参考价值。
概况
小编在工作中偶遇Deadlock的问题,这个对程序员而言是可怕,尤其是对一个从没有遇到过这个问题的小编来说真的是瑟瑟发抖,不过问题总的解决,所以还是要一步步分析一步步排查,这就是成长,哈哈。
问题
为了能脱离小编所在业务，并能完整的描述问题。小编模拟了得问题如下:
mysql 版本为8.0
-- 创建表结构
CREATE TABLE t(
`id` int NOT NULL AUTO_INCREMENT,
`s_id` int(11) NOT NULL COMMENT 'student_id 学生Id',
`name` varchar(40) COLLATE utf8_bin DEFAULT NULL COMMENT '姓名',
PRIMARY KEY (`id`),
KEY `idx_s_id` (`s_id`)
) ENGINE=InnoDB AUTO_INCREMENT=1 DEFAULT CHARSET=utf8 COLLATE=utf8_bin ;
-- 初始化数据
INSERT INTO t(s_id,name) VALUES(1,'name1'),(2,'name2'),(3,'name3'),(4,'name4'),(5,'name5'),(6,'name6'),(7,'name7'),(8,'name8'),(9,'name9'),(10,'name10');
| session1 | session2 |
|---|---|
| start transaction | - |
| update t set name=‘cName11‘ where s_id=11； ## ==s_id=11不存在== | start transaction |
| - | update t set name=‘cName12‘ where s_id=12； ## s_id=12不存在 |
| INSERT INTO t(s_id,name) VALUES(11,‘name11‘) ## ==waitting | - |
| - | INSERT INTO t(s_id,name) VALUES(12,‘name12‘) |
| - | ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction |
好了，进过上述步骤之后，出现了可怕的Deadlock,我看使用命令查看 SHOW ENGINE InnoDB status \G;
mysql> SHOW ENGINE InnoDB status \G;
*************************** 1. row ***************************
Type: InnoDB
Name:
Status:
=====================================
2019-07-29 10:59:40 0x7f47a0117700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 16 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 57 srv_active, 0 srv_shutdown, 27956 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 58
OS WAIT ARRAY INFO: signal count 63
RW-shared spins 19, rounds 30, OS waits 11
RW-excl spins 13, rounds 51, OS waits 0
RW-sx spins 1, rounds 1, OS waits 0
Spin rounds per wait: 1.58 RW-shared, 3.92 RW-excl, 1.00 RW-sx
------------------------
LATEST DETECTED DEADLOCK
------------------------
2019-07-29 10:56:58 0x7f47a0117700
*** (1) TRANSACTION:
TRANSACTION 98735, 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 9, OS thread handle 139945604609792, query id 1491 localhost root update
INSERT INTO t(s_id,name) VALUES(11,'name11')
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 136 page no 5 n bits 80 index idx_s_id of table `jackpot1`.`t` trx id 98735 lock_mode X insert intention waiting
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
0: len 8; hex 73757072656d756d; asc supremum;;
*** (2) TRANSACTION:
TRANSACTION 98734, ACTIVE 40 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 8, OS thread handle 139945604904704, query id 1492 localhost root update
INSERT INTO t(s_id,name) VALUES(12,'name12')
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 136 page no 5 n bits 80 index idx_s_id of table `jackpot1`.`t` trx id 98734 lock_mode X
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
0: len 8; hex 73757072656d756d; asc supremum;;
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 136 page no 5 n bits 80 index idx_s_id of table `jackpot1`.`t` trx id 98734 lock_mode X insert intention waiting
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
0: len 8; hex 73757072656d756d; asc supremum;;
*** WE ROLL BACK TRANSACTION (2)
------------
TRANSACTIONS
------------
Trx id counter 98736
Purge done for trx's n:o < 98721 undo n:o < 15 state: running but idle
History list length 74
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421420599174496, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421420599173592, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421420599172688, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421420599170880, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 98735, ACTIVE 190 sec
4 lock struct(s), heap size 1136, 3 row lock(s), undo log entries 1
MySQL thread id 9, OS thread handle 139945604609792, query id 1491 localhost root
TABLE LOCK table `jackpot1`.`t` trx id 98735 lock mode IX
RECORD LOCKS space id 136 page no 5 n bits 80 index idx_s_id of table `jackpot1`.`t` trx id 98735 lock_mode X
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
0: len 8; hex 73757072656d756d; asc supremum;;
RECORD LOCKS space id 136 page no 5 n bits 80 index idx_s_id of table `jackpot1`.`t` trx id 98735 lock_mode X insert intention
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
0: len 8; hex 73757072656d756d; asc supremum;;
RECORD LOCKS space id 136 page no 5 n bits 80 index idx_s_id of table `jackpot1`.`t` trx id 98735 lock_mode X locks gap before rec
Record lock, heap no 12 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 4; hex 8000000b; asc ;;
1: len 4; hex 8000000b; asc ;;
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (read thread)
I/O thread 5 state: waiting for completed aio requests (read thread)
I/O thread 6 state: waiting for completed aio requests (write thread)
I/O thread 7 state: waiting for completed aio requests (write thread)
I/O thread 8 state: waiting for completed aio requests (write thread)
I/O thread 9 state: waiting for completed aio requests (write thread)
Pending normal aio reads: [0, 0, 0, 0] , aio writes: [0, 0, 0, 0] ,
ibuf aio reads:, log i/o's:, sync i/o's:
Pending flushes (fsync) log: 0; buffer pool: 0
18651 OS file reads, 1447 OS file writes, 760 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 105, seg size 107, 2 merges
merged operations:
insert 18, delete mark 0, delete 0
discarded operations:
insert 0, delete mark 0, delete 0
Hash table size 34679, node heap has 2 buffer(s)
Hash table size 34679, node heap has 2 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 1 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 2 buffer(s)
Hash table size 34679, node heap has 5 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 1130751648
Log buffer assigned up to 1130751648
Log buffer completed up to 1130751648
Log written up to 1130751648
Log flushed up to 1130751648
Added dirty pages up to 1130751648
Pages flushed up to 1130751648
Last checkpoint at 1130751648
427 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 137363456
Dictionary memory allocated 597484
Buffer pool size 8192
Free buffers 1024
Database pages 7156
Old database pages 2621
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 21371, not young 75108
0.00 youngs/s, 0.00 non-youngs/s
Pages read 18577, created 194, written 796
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 7156, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Process ID=1, Main thread ID=139945114007296 , state=sleeping
Number of rows inserted 226, updated 459, deleted 71, read 7457495
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
1 row in set (0.00 sec)
ERROR:
No query specified我们从关键字LATEST DETECTED DEADLOCK开始看发现
(1) TRANSACTION:(1) WAITING FOR THIS LOCK TO BE GRANTED(2) TRANSACTION:(2) HOLDS THE LOCK(S):(2) WAITING FOR THIS LOCK TO BE GRANTED:
可以看出是在执行INSERT语句的时候发生Deadlock的，但还是无法确定为什么出现问题，这时我们表performance_schema.data_locks通过查看
-- 第一次执行INSERT时执行，打印lock的情况
mysql> SELECT `ENGINE`,THREAD_ID,EVENT_ID,OBJECT_SCHEMA,OBJECT_NAME,INDEX_NAME,OBJECT_INSTANCE_BEGIN,LOCK_TYPE,LOCK_MODE,LOCK_STATUS,LOCK_DATA FROM performance_schema.data_locks ;
+--------+-----------+----------+---------------+-------------+------------+-----------------------+-----------+-----------+-------------+------------------------+
| ENGINE | THREAD_ID | EVENT_ID | OBJECT_SCHEMA | OBJECT_NAME | INDEX_NAME | OBJECT_INSTANCE_BEGIN | LOCK_TYPE | LOCK_MODE | LOCK_STATUS | LOCK_DATA |
+--------+-----------+----------+---------------+-------------+------------+-----------------------+-----------+-----------+-------------+------------------------+
| INNODB | 48 | 119 | jackpot1 | t | NULL | 139945536711608 | TABLE | IX | GRANTED | NULL |
| INNODB | 48 | 119 | jackpot1 | t | idx_s_id | 139945536708664 | RECORD | X | GRANTED | supremum pseudo-record |
| INNODB | 47 | 150 | jackpot1 | t | NULL | 139945536705784 | TABLE | IX | GRANTED | NULL |
| INNODB | 47 | 150 | jackpot1 | t | idx_s_id | 139945536702744 | RECORD | X | GRANTED | supremum pseudo-record |
| INNODB | 47 | 151 | jackpot1 | t | PRIMARY | 139945536703776 | RECORD | X | GRANTED | supremum pseudo-record |
+--------+-----------+----------+---------------+-------------+------------+-----------------------+-----------+-----------+-------------+------------------------+
5 rows in set (0.00 sec)
-- 第二次执行INSERT时执行，打印lock的情况
mysql> SELECT `ENGINE`,THREAD_ID,EVENT_ID,OBJECT_SCHEMA,OBJECT_NAME,INDEX_NAME,OBJECT_INSTANCE_BEGIN,LOCK_TYPE,LOCK_MODE,LOCK_STATUS,LOCK_DATA FROM performance_schema.data_locks ;
+--------+-----------+----------+---------------+-------------+------------+-----------------------+-----------+--------------------+-------------+------------------------+
| ENGINE | THREAD_ID | EVENT_ID | OBJECT_SCHEMA | OBJECT_NAME | INDEX_NAME | OBJECT_INSTANCE_BEGIN | LOCK_TYPE | LOCK_MODE | LOCK_STATUS | LOCK_DATA |
+--------+-----------+----------+---------------+-------------+------------+-----------------------+-----------+--------------------+-------------+------------------------+
| INNODB | 47 | 150 | jackpot1 | t | NULL | 139945536705784 | TABLE | IX | GRANTED | NULL |
| INNODB | 47 | 150 | jackpot1 | t | idx_s_id | 139945536702744 | RECORD | X | GRANTED | supremum pseudo-record |
| INNODB | 47 | 151 | jackpot1 | t | PRIMARY | 139945536703776 | RECORD | X | GRANTED | supremum pseudo-record |
| INNODB | 47 | 152 | jackpot1 | t | PRIMARY | 139945536704120 | RECORD | X,GAP | GRANTED | 14 |
| INNODB | 47 | 152 | jackpot1 | t | idx_s_id | 139945536704464 | RECORD | X,INSERT_INTENTION | GRANTED | supremum pseudo-record |
| INNODB | 47 | 152 | jackpot1 | t | idx_s_id | 139945536704808 | RECORD | X,GAP | GRANTED | 12, 14 |
+--------+-----------+----------+---------------+-------------+------------+-----------------------+-----------+--------------------+-------------+------------------------+
6 rows in set (0.00 sec)分析第一次执行
我们发现EVENT_ID为119和150为执行update产生的先是表级别执行IX Lock，然后行级别执行Next-Key Lock，这里的字段
LOCK_DATA内容supremum pseudo-record很重要，我通过在Mysql官方文档上查询得意思为
For the last interval, the next-key lock locks the gap above the largest
value in the index and the “supremum” pseudo-record having a value higher
than any value actually in the index. The supremum is not a real index
record, so, in effect, this next-key lock locks only the gap following the
largest index value.我们google翻译一下
对于最后一个间隔，下一个键锁定将间隙锁定在索引中最大值之上，而“ supremum ”
伪记录的值高于索引中实际的任何值。supremum不是真正的索引记录，因此，实际上，
此下一键锁定仅锁定最大索引值之后的间隙。就是说supremun是伪记录的值高于索引中实际任何值，说白了就是，在最大索引值的屁股后面，这个性质也就是Next-Key Lock
根据Next-Key Locks的定义如下
A next-key lock is a combination of a record lock on the index record and a gap lock on the gap before the index record.
InnoDB performs row-level locking in such a way that when it searches or scans a table index, it sets shared or exclusive locks on the index records it encounters. Thus, the row-level locks are actually index-record locks. A next-key lock on an index record also affects the “gap” before that index record. That is, a next-key lock is an index-record lock plus a gap lock on the gap preceding the index record. If one session has a shared or exclusive lock on record R in an index, another session cannot insert a new index record in the gap immediately before R in the index order.这里有句注意了，我们要划重点，因为后面的分析需要用到
If one session has a shared or exclusive lock on record R in an index, another session cannot insert a new index record in the gap immediately before R in the index order.
意思就是
如果一个会话R在索引中具有共享或独占锁定记录 ，则另一个会话不能R在索引顺序之前的间隙中插入新索引记录 。 至此我们也就明白为什么第一条INSERT为什么会处于等待状态了，因为INSERT的时候需要等待Session2 update X锁的释放；若等待太久则Mysql会有自我保护功能提示超时放弃ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction
- 分析第二次执行
我们发现执行第二次INSERT就直接Deadlock,这里我们也就明白为什么了吧，因为Session1 INSERT 等待Session2 update的X锁释放，而Session2 INSERT 等待Session1 update的X锁释放，这就构成了典型的死锁。而Mysql会有ROLLBACK机制，任意回滚其中一个Session，也就意味着释放了其中的一个update hold X锁，让另一个Session成功执行完毕。
哦还有，这里 EVENT_ID 152的记录中LOCK_DATA字段内容12, 14又是什么意思呢？
答：非唯一索引对应的唯一索引值是GAP锁的特征Mysql官方文档可查，即12表示s_id,14表示id，
好了讲到这里这一次的Deadlock问题已经被解决了，我们来总结一下吧。
- 1 遇到问题需要结合搜索引擎和经验一步步分析，耐心不要放弃。
- 2 在平时的项目中尽量不要update不存在的记录
以上是关于Mysql死锁分析案例的主要内容，如果未能解决你的问题，请参考以下文章