【重温mysql】7、死锁与innodb状态日志

2,806 阅读14分钟

InnoDB 采取行级加锁策略,虽然行级加锁策略极大提高了程序的并发性能,但由于锁粒度的减小 InnoDB 执行某些操作的时候可能会同时占用多个行锁,加大了锁冲突的概率;不同事务隔离级别对数据一致性要求不同,如RR级别下增加的gap锁可能导致大量的锁冲突;同时不当的业务设计也可能造成死锁。死锁会占用系统资源阻塞请求,轻则影响 sql 执行效率拖慢系统,重则拖垮服务器导致服务不可用。因此我们在使用过程中需要尽量避免死锁的发生,在遇到死锁时能够依据相关信息排查死锁加以防范。

死锁机制

首先我们来温习一下导致死锁的四个必要条件:

  • 互斥,一个资源每次只能被一个进程使用。
  • 请求与占用,一个进程因请求资源而阻塞时,对已获得的资源保持不放。
  • 不剥夺,进程已获得的资源,在该进程末使用完之前,不能强行剥夺。
  • 循环等待,若干进程之间形成一种头尾相接的循环等待资源关系。

同样,InnoDB 中的死锁形成也需要满足上述四个条件。在 InnoDB 中造成死锁,那么一定是在多个线程同时操作同一份数据时才会产生,即存在两个或以上的事务,考虑如下场景,给定表test,表结构如下:

CREATE TABLE `test` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `name` varchar(30) NOT NULL DEFAULT '',
  PRIMARY KEY (`id`)
) ENGINE=InnoDB;

预置数据如下:

id name
1 张三
2 李四
3 王五

现在按照如下操作,删除两条张三与李四两条数据:

序号 事务1 状态 事务2 状态
1 begain transaction;
2 delete from test where id = 1; 执行成功,持有id=1的X锁
3 begain transaction;
4 delete from test where id = 2; 执行成功,持有id=2的X锁
5 delete from test where id = 2; 等待事务2释放锁
6 delete from test where id = 1; 等待事务1释放锁。系统检测到死锁,回滚事务2
7 commit;
8 commit;

在上述操作过程中,我们构造了一个非常典型的死锁条件,InnoDB 死锁机制检测到了死锁,会选择性回滚权重小的事务。通过语句可以查询死锁状态:

show engine innodb status;

从上述执行过程我们可以看出InnoDB 可以检测出死锁,那么 InnoDB 又是如何检测死锁的呢?

InnoDB 死锁策略

InnoDB 有两种死锁处理方式:

  • 等待,直到超时(通过innodb_lock_wait_timeout参数控制)
  • 死锁检测,主动回滚一条事务,让其他事务继续执行(innodb_deadlock_detect=on),该机制只适用于只有行锁的情形

InnoDB 中的死锁检测是通过Waiting For Graph算法实现的。在 InnoDB 中,会记录所有事务的锁形成一个以事务为顶点,锁为边的有向图。只需判断该有向图中是否存在回环,即可知道有无死锁存在。在上述死锁场景中,事务1在等待事务2释放ID=2的锁,而事务2也在等待事务1释放ID=1的锁,形成了回环结构,因此 InnoDB 判断系统中存在死锁。

那么假设存在很多个事务,事务的相互等待,形成了一条非常长的等待链的时候InnoDB 将会如何处理呢? 在这种情况下,当 InnoDB 等待图列表长度超出了 200 的时候,InnoDB 认为当中出现了死锁。 此外当等待链上事务持有锁过多的时(需要对获得超过1,000,000个行锁),InnoDB 也认为当中出现了死锁。

InnoDB 检测到死锁后,是如何释放一个事务的呢?,InnoDB 通过事务权重来判定事务重要程度,权重低的会释放掉,事务权重一般是通过执行事务中的语句插入、更新、删除语句影响数据条数得出的,事务语句影响数据条数越小,该事务权重越低。

InnoDB 状态分析

我们可以通过如下语句来查看系统中是否存在死锁,如若存在死锁,状态日志将显示最后一次死锁信息,可以通过日志粗略查看死锁相关的事务与锁情况:

show engine innodb status;

一个标准的状态日志如下:

=====================================
2019-11-19 23:19:23 0x7fa850f58700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 48 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 852151 srv_active, 0 srv_shutdown, 4608208 srv_idle
srv_master_thread log flush and writes: 5459518
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 2440006
OS WAIT ARRAY INFO: signal count 2411688
RW-shared spins 0, rounds 1948637, OS waits 972484
RW-excl spins 0, rounds 1702845, OS waits 160434
RW-sx spins 4496, rounds 134826, OS waits 4138
Spin rounds per wait: 1948637.00 RW-shared, 1702845.00 RW-excl, 29.99 RW-sx
------------------------
LATEST DETECTED DEADLOCK
------------------------
2019-11-19 23:19:08 0x7fa860156700
*** (1) TRANSACTION:
TRANSACTION 25321837, ACTIVE 29 sec starting index read
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 2348540, OS thread handle 140360898553600, query id 66353526 163.125.229.225 root updating
delete from test where id = 2
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 2266 page no 3 n bits 80 index PRIMARY of table `test`.`test` trx id 25321837 lock_mode X locks rec but not gap waiting
Record lock, heap no 6 PHYSICAL RECORD: n_fields 4; compact format; info bits 32
 0: len 4; hex 80000002; asc     ;;
 1: len 6; hex 000001826186; asc     a ;;
 2: len 7; hex 65000001250c88; asc e   %  ;;
 3: len 6; hex e69d8ee59b9b; asc       ;;

*** (2) TRANSACTION:
TRANSACTION 25321862, ACTIVE 15 sec starting index read
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 2348917, OS thread handle 140361143248640, query id 66353634 163.125.229.225 root updating
delete from test where id = 1
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 2266 page no 3 n bits 80 index PRIMARY of table `test`.`test` trx id 25321862 lock_mode X locks rec but not gap
Record lock, heap no 6 PHYSICAL RECORD: n_fields 4; compact format; info bits 32
 0: len 4; hex 80000002; asc     ;;
 1: len 6; hex 000001826186; asc     a ;;
 2: len 7; hex 65000001250c88; asc e   %  ;;
 3: len 6; hex e69d8ee59b9b; asc       ;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 2266 page no 3 n bits 80 index PRIMARY of table `test`.`test` trx id 25321862 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 80000001; asc     ;;
 1: len 6; hex 00000182616d; asc     am;;
 2: len 7; hex 58000001412fef; asc X   A/ ;;
 3: len 6; hex e5bca0e4b889; asc       ;;

*** WE ROLL BACK TRANSACTION (2)
------------
TRANSACTIONS
------------
Trx id counter 25321913
Purge done for trx's n:o < 25321911 undo n:o < 0 state: running but idle
History list length 35
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421836854896032, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421836854885088, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421836854895120, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421836854891472, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421836854888736, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421836854886912, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421836854900592, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421836854898768, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421836854893296, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421836854892384, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421836854890560, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421836854886000, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421836854883264, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 25321912, ACTIVE 0 sec
5 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 2
MySQL thread id 2346328, OS thread handle 140360896157440, query id 66354003 47.98.152.73 root
Trx read view will not see trx with id >= 25321911, sees < 25321837
---TRANSACTION 25321837, ACTIVE 44 sec
3 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 2
MySQL thread id 2348540, OS thread handle 140360898553600, query id 66353526 163.125.229.225 root
--------
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
846404 OS file reads, 16785073 OS file writes, 5999964 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 8.37 writes/s, 3.17 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 185, seg size 187, 28201 merges
merged operations:
 insert 528, delete mark 7663041, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 138389, node heap has 31 buffer(s)
Hash table size 138389, node heap has 2 buffer(s)
Hash table size 138389, node heap has 3983 buffer(s)
Hash table size 138389, node heap has 218 buffer(s)
Hash table size 138389, node heap has 5 buffer(s)
Hash table size 138389, node heap has 1 buffer(s)
Hash table size 138389, node heap has 2 buffer(s)
Hash table size 138389, node heap has 5 buffer(s)
139.08 hash searches/s, 4.46 non-hash searches/s
---
LOG
---
Log sequence number 24370884626
Log flushed up to   24370882478
Pages flushed up to 24370875924
Last checkpoint at  24370875333
0 pending log flushes, 0 pending chkp writes
9315962 log i/o's done, 2.31 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 549715968
Dictionary memory allocated 10240009
Buffer pool size   32764
Free buffers       1024
Database pages     27493
Old database pages 10128
Modified db pages  34
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 964069, not young 143276717
0.00 youngs/s, 0.00 non-youngs/s
Pages read 845408, created 77961, written 6649614
0.00 reads/s, 0.04 creates/s, 5.40 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: 27493, unzip_LRU len: 0
I/O sum[276]:cur[1], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Process ID=1773, Main thread ID=140361173219072, state: sleeping
Number of rows inserted 19006577, updated 853025, deleted 5584787, read 210247854332
0.85 inserts/s, 0.83 updates/s, 0.06 deletes/s, 21633.22 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

InnoDB 标准监控信息一共包含了输出头主线程负载信号量死锁信息事务信息IO相关信息插入缓冲和自适应哈希索引相关信息日志信息缓冲池和内存使用情况行操作信息。通过这些内部状态信息我们可以了解到InnoDB 内部实际的负载情况,对于数据库运维有着重要的作用。

输出头

标准监控信息输出头包含如下几个部分,显示了当前监控的查询时间、监控名称、本次输出与上次输出时间间隔秒数。

后台线程信息

该部分显示了后台 innodb 主线程的工作负载情况。一般来说,srv_active 越大,srv_idle 越小表明当前mysql数据库压力不大。

信号量信息

信号量部分统计了线程空转次数以及等待获取互斥锁或读写锁信号量的次数。这里的互斥锁和读写锁指的是mysql中的Latch,主要目的为保证并发线程操作临界资源的正确性。如果有大量线程在等待信号量,可能是由于磁盘 IO 性能瓶颈或 InnoDB 内部资源争夺激烈导致,而InnoDB 内部资源一般是由于并行查询过多或操作系统线程调度发生了问题。如若 os_waits 次数较高,表明 latch 争夺比较频繁。

最新死锁信息

该部分显示了最后一次发生死锁时的死锁信息。死锁信息里面有一些非常有用的信息如加锁与等待锁的语句、加锁使用的索引等信息,但遗憾的是该处日志并不会显示持有和等待的锁,这对于多个线程引发的死锁来讲并不是那么容易分析。

事务信息

事务信息显示了当前innodb中前一段时间的相关事务情况,有助于我们排查死锁。

文件IO信息

该部分显示了后台线程的IO情况。

插入缓冲与自适应哈希索引信息

该部分显示了插入缓冲执行情况与自适应哈希索引相关信息。

日志信息

日志信息显示了重做日志的当前情况。

缓冲池与内存信息

这部分显示了缓冲池中的页读写统计及其内存使用统计。

行操作信息

这部分显示了主线程正在做什么,如各种类型的行操作的数量和性能统计。

如何避免死锁

为了减小死锁对系统的影响,我们应该尽可能避免死锁。通常有如下技巧可以用于避免死锁:

  • 使用事务,尽量不用lock tables 此类表锁,存在多种锁类型的情况下,InnoDB 无法进行死锁检测,只能等待死锁超时。
  • 尽量减小事务执行时间,避免长事务,长事务可能持有锁时间过长,更易引发死锁。
  • 降低隔离级别,RC 级别下不存在间隙锁,将极大减小死锁产生的概率。
  • MDL语句修改多个表或或行数据的时候,需要保持操作顺序一致,以免不恰当的加锁过程产生死锁。
  • MDL语句尽量使用主键或索引,InnoDB 加锁是对索引进行加锁,使用主键或索引可以降低锁冲突的概率。
  • 如若由于业务需要无法避免死锁,可以考虑通过表锁或分布式锁加以控制。

对于 InnoDB 来说死锁成因非常复杂,需要具体问题具体分析,在《常见的 MySQL 死锁案例分析》一文的作者已经对常见的一些死锁场景进行了收集整理,有兴趣的同学可以查阅加深对死锁的理解与分析。

感谢