定位 MySQL 死锁或事务阻塞的思路以及修复的方法

2022-08-18 18:51:54

Overview

目前业务涉及到了一个上 TB 级的数据库，因为维护的项目已经有很多年了，所以该项目的数据库设计模式还是参考了之前的范式涉及，导致大量使用了外键。又因为项目的特点，为了保持幂等，又大量使用了 MySQL 的 upsert 语法。所以最近终于扛不住开始出现大范围的 gap lock 和死锁，导致数据库需要不停的检测死锁回滚以及杀死 hang 住的请求。当所有 worker 都被阻塞之后最终导致相关热表再无响应，刷新数据的程序假死。

Find out the issue
为了解决这个问题，我们先要定位问题。当时使用 show processlist 能看到的现象就是大量使用 upsert 的语句执行时间变长。
我的第一反应是查看一下当下事务的情况和锁获取的情况。
关于解决这种问题在 MySQL 中我觉得应该重点关注以下一个命令和三个表

show engine innodb status;
information_schema.INNODB_TRX
information_schema.LOCKS
information_schema.INNODB_LOCK_WAITS

当然你不一定会有 show engine status 的权限，所以建议使用下面三个表结合来看目前到底发生了什么。
我们可以先使用
select * from INNODB_TRX order by trx_rows_locked DESC
查看目前还在活跃的事务情况，并且根据锁住的行数简单排个序。

从该图我们可以很容易看出到底是哪些事务目前处于等锁状态，以及是谁锁住他们。结合这个信息我们可以找到叫 trx_requested_lock_id 的字段。该字段结合 information_schema.LOCKS lock_id 变可以查询到目前该事务等锁目标的情况。
包括正在等待的锁的类型，锁的模式，锁的表，账锁住的 index 等如下图。

从该图我们可以注意到，delmondo.YouTubePostSummaries 这张表被加了大量的 x_gap 锁。我们可以推测，通过查看 information_schema.INNODB_TRX 表我们可以查看到执行 SQL，发现有大量的 upsert 操作(INSERT ON DUPLICATE UPDATE)导致我们被加上了大量的 gap lock 。从而导致了大量的互相等待，最终严重影响了我们的查询性能。
再多提一点，如果我们权限够的话我们也可以直接使用

show engine innodb status;

来查看当时数据库的情况。

------------------------
LATEST DETECTED DEADLOCK
------------------------
2022-01-20 04:23:30 0x7fe29d264700
*** (1) TRANSACTION:
TRANSACTION 30081990607, ACTIVE 1 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 17 lock struct(s), heap size 1136, 10 row lock(s), undo log entries 3
MySQL thread id 17820, OS thread handle 140611271272192, query id 18353799 10.72.1.214 social-circulate-1 update
INSERT INTO `FacebookVideoRetentions` (`b000`,`b001`,`b002`,`b003`,`b004`,`b005`,`b006`,`b007`,`b008`,`b009`,`b010`,`b011`,`b012`,`b013`,`b014`,`b015`,`b016`,`b017`,`b018`,`b019`,`b020`,`b021`,`b022`,`b023`,`b024`,`b025`,`b026`,`b027`,`b028`,`b029`,`b030`,`b031`,`b032`,`b033`,`b034`,`b035`,`b036`,`b037`,`b038`,`b039`,`b040`,`viewType`,`FacebookVideoId`,`createdAt`,`updatedAt`) VALUES (0.9832,0.8267,0.6054,0.5434,0.4943,0.4471,0.4186,0.3969,0.3825,0.3722,0.3554,0.3413,0.3251,0.3027,0.2094,0.2024,0.1967,0.1939,0.1899,0.1867,0.1836,0.1792,0.176,0.1746,0.1726,0.1702,0.1654,0.1631,0.1612,0.1586,0.1559,0.1529,0.1515,0.1501,0.149,0.1481,0.1475,0.1467,0.1455,0.1447,0.141,'AUTO',16313014,'2022-01-20 04:23:30','2022-01-20 04:23:30') ON DUPLICATE KEY UPDATE `b000`=VALUES(`b000`), `b001`=VALUES(`b001`), `b002`=VALUES(`b002`), `b003`=VALUES(`b003`), `b004`=VALUES(`b004`), `b005`=VALUES(`b005`), `b006`=VALUES(`
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 290 page no 180626 n bits 160 index PRIMARY of table `delmondo`.`FacebookVideoRetentions` trx id 30081990607 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 30081989026, ACTIVE 2 sec inserting
mysql tables in use 1, locked 1
23 lock struct(s), heap size 3520, 13 row lock(s), undo log entries 3
MySQL thread id 17810, OS thread handle 140611275867904, query id 18353798 10.72.1.231 social-circulate-1 update
INSERT INTO `FacebookVideoRetentions` (`b000`,`b001`,`b002`,`b003`,`b004`,`b005`,`b006`,`b007`,`b008`,`b009`,`b010`,`b011`,`b012`,`b013`,`b014`,`b015`,`b016`,`b017`,`b018`,`b019`,`b020`,`b021`,`b022`,`b023`,`b024`,`b025`,`b026`,`b027`,`b028`,`b029`,`b030`,`b031`,`b032`,`b033`,`b034`,`b035`,`b036`,`b037`,`b038`,`b039`,`b040`,`viewType`,`FacebookVideoId`,`createdAt`,`updatedAt`) VALUES (0.9859,0.9717,0.4367,0.3036,0.2448,0.2094,0.1886,0.1647,0.1481,0.1353,0.1262,0.1197,0.1155,0.1106,0.1057,0.0979,0.0902,0.0858,0.0812,0.0755,0.0709,0.0688,0.0665,0.0639,0.0632,0.061,0.0601,0.0586,0.0567,0.0549,0.0534,0.0515,0.0476,0.0453,0.0442,0.0428,0.0363,0.0314,0.0275,0.0231,0.0162,'AUTO',16295268,'2022-01-20 04:23:30','2022-01-20 04:23:30') ON DUPLICATE KEY UPDATE `b000`=VALUES(`b000`), `b001`=VALUES(`b001`), `b002`=VALUES(`b002`), `b003`=VALUES(`b003`), `b004`=VALUES(`b004`), `b005`=VALUES(`b005`), `b006`=VALUES
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 290 page no 180626 n bits 160 index PRIMARY of table `delmondo`.`FacebookVideoRetentions` trx id 30081989026 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 290 page no 180626 n bits 160 index PRIMARY of table `delmondo`.`FacebookVideoRetentions` trx id 30081989026 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 (1)

9 lock struct(s), heap size 1136, 6 row lock(s), undo log entries 1
MySQL thread id 15079, OS thread handle 140611428878080, query id 15078047 10.72.2.62 social-circulate-1 query end
INSERT INTO `TwitterPostSummaries` (`retweets`,`likes`,`TwitterPostId`,`createdAt`,`updatedAt`) VALUES (0,2,166986677,'2022-01-20 04:20:40','2022-01-20 04:20:40') ON DUPLICATE KEY UPDATE `retweets`=VALUES(`retweets`), `likes`=VALUES(`likes`), `TwitterPostId`=VALUES(`TwitterPostId`), `updatedAt`=VALUES(`updatedAt`)
---TRANSACTION 30080926855, ACTIVE 1 sec inserting
mysql tables in use 1, locked 1
ROLLING BACK 8 lock struct(s), heap size 1136, 4 row lock(s)
MySQL thread id 16539, OS thread handle 140611233146624, query id 15078037 10.72.1.219 social-circulate-1 update
INSERT INTO `TwitterPostSummaries` (`retweets`,`likes`,`TwitterPostId`,`createdAt`,`updatedAt`) VALUES (32,525,166467513,'2022-01-20 04:20:39','2022-01-20 04:20:39') ON DUPLICATE KEY UPDATE `retweets`=VALUES(`retweets`), `likes`=VALUES(`likes`), `TwitterPostId`=VALUES(`TwitterPostId`), `updatedAt`=VALUES(`updatedAt`)
---TRANSACTION 30080926830, ACTIVE 1 sec inserting
mysql tables in use 1, locked 1
ROLLING BACK 8 lock struct(s), heap size 1136, 4 row lock(s)
MySQL thread id 15683, OS thread handle 140611373999872, query id 15077993 10.72.2.40 social-circulate-1 update
INSERT INTO `TwitterPostSummaries` (`retweets`,`likes`,`TwitterPostId`,`createdAt`,`updatedAt`) VALUES (0,1,167851835,'2022-01-20 04:20:42','2022-01-20 04:20:42') ON DUPLICATE KEY UPDATE `retweets`=VALUES(`retweets`), `likes`=VALUES(`likes`), `TwitterPostId`=VALUES(`TwitterPostId`), `updatedAt`=VALUES(`updatedAt`)
---TRANSACTION 30080926779, ACTIVE 1 sec inserting
mysql tables in use 1, locked 1
ROLLING BACK 5 lock struct(s), heap size 1136, 4 row lock(s)
MySQL thread id 16097, OS thread handle 140611218822912, query id 15077924 10.72.1.194 social-circulate-1 update
INSERT INTO `TwitterPostSummaries` (`retweets`,`likes`,`TwitterPostId`,`createdAt`,`updatedAt`) VALUES (1,5,166257779,'2022-01-20 04:20:41','2022-01-20 04:20:41') ON DUPLICATE KEY UPDATE `retweets`=VALUES(`retweets`), `likes`=VALUES(`likes`), `TwitterPostId`=VALUES(`TwitterPostId`), `updatedAt`=VALUES(`updatedAt`)
---TRANSACTION 30080926195, ACTIVE 1 sec starting index read
mysql tables in use 1, locked 1
6 lock struct(s), heap size 1136, 3 row lock(s)
MySQL thread id 15674, OS thread handle 140611412657920, query id 15077041 10.72.1.235 social-circulate-1 update
INSERT INTO `TwitterPostSummaries` (`retweets`,`likes`,`TwitterPostId`,`createdAt`,`updatedAt`) VALUES (2,27,167417844,'2022-01-20 04:20:42','2022-01-20 04:20:42') ON DUPLICATE KEY UPDATE `retweets`=VALUES(`retweets`), `likes`=VALUES(`likes`), `TwitterPostId`=VALUES(`TwitterPostId`), `updatedAt`=VALUES(`updatedAt`)
---TRANSACTION 30080925558, ACTIVE 1 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 6 lock struct(s), heap size 1136, 3 row lock(s)
MySQL thread id 15195, OS thread handle 140611294521088, query id 15075747 10.72.1.211 social-circulate-1 update
INSERT INTO `TwitterPostSummaries` (`retweets`,`likes`,`TwitterPostId`,`createdAt`,`updatedAt`) VALUES (0,0,166112095,'2022-01-20 04:20:39','2022-01-20 04:20:39') ON DUPLICATE KEY UPDATE `retweets`=VALUES(`retweets`), `likes`=VALUES(`likes`), `TwitterPostId`=VALUES(`TwitterPostId`), `updatedAt`=VALUES(`updatedAt`)
------- TRX HAS BEEN WAITING 0 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 233 page no 1108050 n bits 400 index PRIMARY of table `delmondo`.`TwitterPostSummaries` trx id 30080925558 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 55

我们能直接通过该命令查看到当前检测到的死锁，以及正在等待锁的事务和回滚的事务。

Fix the issue

当然发现和明确了问题之后，解决问题的方法有很多。
既然发现是因为 gap 锁引起的死锁问题，我们可以在确保隔离级别不会影响到其他逻辑的情况下，降低隔离级别到 RC(READ COMMITTED), 就不会再对该行加 gap 锁了，从而解决这个问题。当然我们也可以不修改相关的隔离级别。因为通常情况下数据库使用隔离级别都是全局的，修改可能会引起因为依赖隔离级别的特性的代码出现数据修改和查询出现不一致的问题。所以一般我们不会去直接修改隔离级别除非特别确信。我们可以找到那些使用 upsert 的地方，将他们拆开。通过查询，再自行判断插入或者更新操作，可以避免加相关的 gap lock，来避免这个问题。

我们再延伸一下这个话题，因为使用 upsert 的操作是比较昂贵的。一般除了我们明确知道我们的系统可以承受一定的性能损失或者是低速访问的情况下，不应该在高频访问的情景下使用。我们来讨论一下当我们使用 MySQL INNODB 的 upsert(INSERT ON DUPLICATE UPDATE) 操作时发生了什么。

在 MySQL 中 INSERT ON DUPLICATE UPDATE 的加锁流程：
1. Innodb 存储引擎尝试 INSER INTO 操作
2. 如果插入成功，则忽略 DUPLICATE UPDATE 部分并返回
3. 如果插入失败，则表明有相同记录存在，对该记录加共享锁(S)
4. 执行DUPLICATE UPDATE语句，对记录加 X 锁，然后更新记录。

在MySQL默认隔离级别REPEATABLE READ下，为避免出现"幻读"发生，防止其他会话插入相同键值的记录。
对于普通INSERT操作加锁如下：
1. 对于非唯一索引，需要对新记录加排他锁(X)，另外对新记录和新记录的相邻记录的区间加gap锁。
2. 对于唯一索引，仅需要对新记录加排他锁(X)，唯一索引特性保证其他会话无法插入相同键值。

对于INSERT ON DUPLICATE UPDATE操作，当表中未存在重复键值记录时，加锁特点如下：
1. 对于唯一索引和非唯一索引，都需要对新记录加排他锁(X)，另外对新记录和新记录的相邻记录的区间加gap锁。

当在 RR 级别的隔离事务下面我们在大区间大量加 gap lock 锁导致互相锁住。然后解锁回滚，再加锁。于是出现了上面的情况。
其实我个人觉得, 在互联网业务中还是尽量使用 RC 的隔离级别，并且不要使用外键。因为在高并发大流量的场景下，上述的问题最好是能通过自行加乐观锁解决。或者通过一些别的补偿手段。如果因为添加 gap lock 或者大量 x lock ，亦或者使用大事务造成死锁都会是非常浪费时间难以排查的问题。能避免还是尽量避免。

Reference:

https://zhuanlan.zhihu.com/p/110143157 MySQL事务锁等待超时 Lock wait timeout exceeded

https://www.aneasystone.com/archives/2017/10/solving-dead-locks-one.html 解决死锁之路 - 学习事务与隔离级别

https://blog.csdn.net/w59879213/article/details/6975285. Kill MySQL 杀死指定用户的全部进程

码农公寓

相关文章