关于源码:故障分析-从-Insert-并发死锁分析-Insert-加锁源码逻辑

1次阅读

共计 11006 个字符,预计需要花费 28 分钟才能阅读完成。

作者:李锡超

一个爱笑的江苏苏宁银行 数据库工程师,次要负责数据库日常运维、自动化建设、DMP 平台运维。善于 MySQL、Python、Oracle,喜好骑行、钻研技术。

本文起源:原创投稿

* 爱可生开源社区出品,原创内容未经受权不得随便应用,转载请分割小编并注明起源。


一、前言

死锁,作为数据库一个常见的并发问题。此类问题:

1. 触发起因往往与利用的逻辑相干,参加的事务可能是两个、三个、甚至更多;

2. 因为不同数据库的锁实现机制简直齐全不同、实现逻辑简单,还存在多种锁类型;

3. 数据库产生死锁后,会立刻终止局部事务,预先无奈看到死锁前的期待状态。

即,死锁问题具备业务关联、机制简单、类型多样等特点,导致当数据库产生死锁问题时,不是那么容易剖析。

基于解决死锁问题存在的难点,本文以 MySQL 数据库一则并发 Insert 导致的死锁为例,从发现问题、重现问题、根因剖析、解决问题 4 个步骤,冀望能提供一套对于死锁的迷信无效计划,供读者敌人参考。

二、问题景象

某零碎在进行上线前压测时,发现利用日志存在如下日志提醒触发死锁问题:

Deadlock found when trying to get lock; try restarting transaction

好在压测时,就发现了问题,防止上线后影响生产。

随后,执行 show engine innodb status,有如下内容(脱敏后):

------------------------
LATEST DETECTED DEADLOCK
------------------------
2023-03-24 19:07:50 140736694093568
*** (1) TRANSACTION:
TRANSACTION 56118, ACTIVE 6 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 1192, 1 row lock(s), undo log entries 1
MySQL thread id 9, OS thread handle 140736685700864, query id 57 localhost root update
insert into dl_tab(id,name) values(30,10)

*** (1) HOLDS THE LOCK(S):
RECORD LOCKS space id 11 page no 5 n bits 72 index ua of table `testdb`.`dl_tab` trx id 56118 lock mode S waiting
Record lock, heap no 6 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 4; hex 8000000a; asc     ;;  # 十进制: 10
 1: len 4; hex 8000001a; asc     ;;  # 十进制: 26


*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 11 page no 5 n bits 72 index ua of table `testdb`.`dl_tab` trx id 56118 lock mode S waiting
Record lock, heap no 6 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 4; hex 8000000a; asc     ;;  # 十进制: 10
 1: len 4; hex 8000001a; asc     ;;  # 十进制: 26


*** (2) TRANSACTION:
TRANSACTION 56113, ACTIVE 12 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1192, 2 row lock(s), undo log entries 2
MySQL thread id 8, OS thread handle 140736952903424, query id 58 localhost root update
insert into dl_tab(id,name) values(40,8)

*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 11 page no 5 n bits 72 index ua of table `testdb`.`dl_tab` trx id 56113 lock_mode X locks rec but not gap
Record lock, heap no 6 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 4; hex 8000000a; asc     ;; # 十进制: 10
 1: len 4; hex 8000001a; asc     ;; # 十进制: 26


*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 11 page no 5 n bits 72 index ua of table `testdb`.`dl_tab` trx id 56113 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 6 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 4; hex 8000000a; asc     ;; # 十进制: 10
 1: len 4; hex 8000001a; asc     ;; # 十进制: 26

*** WE ROLL BACK TRANSACTION (1)
------------

1、死锁信息梳理

依据以上信息,发现是 dl_tab 执行 insert 操作导致死锁。初步梳理如下。

版本: 8.0.27

隔离级别: Read-Commited

表构造:

*************************** 1. row ***************************
       Table: dl_tab
Create Table: CREATE TABLE `dl_tab` (
  `id` int NOT NULL AUTO_INCREMENT,
  `name` int NOT NULL,
  PRIMARY KEY (`id`),
  UNIQUE KEY `ua` (`name`)
) ENGINE=InnoDB AUTO_INCREMENT=41 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci

留神,以上 innodb status 输入,不同的数据库版本会有差别。次要有:

A. 在 MySQL 8.0.18 及之后,输入后果包含两个事务各自持有的锁、期待的锁,对剖析死锁问题很有帮忙。在 8.0.18 之前,只包含事务 1 期待的锁,事务 2 持有的锁、期待的锁,而不包含事务 1 持有的锁信息;

B. 以上示例还包含具体的索引记录值(如{10,26}:第一字段为索引记录的值,第二个字段为对应的主键记录)。如果没有索引记录值,可能只有 heap no,该编号作为外部实现锁机制十分要害,但无奈和具体的索引记录对应起来。此外,找了其它几个 MySQL 版本发现原生版本≥5.7.21、≥8.0 有这个性能,Percona mysql 5.7.21 竟然没有这个性能;

C. 事务 T1 期待的锁从输入后果看到的是 LOCK S, 但其实获取的锁是 lock s next key lock, 这点从前面的源码剖析后果中会进一步阐明。

innodb status 日志梳理:

从以上 innodb status 输入。能够看到死锁产生在惟一索引 ua 上。这确实也是在 RC 隔离级别配置下,比拟常见的死锁场景。进一步梳理死锁过程:

A. 首先事务 T1 获取到了 ua 中记录 10 的 lock x,rec not not gap

B. 事务 T2 尝试获取 ua 中记录 10 的lock s, next key lock,因为 T1 持有了记录的独占锁,因而被 T1 梗塞

C. 事务 T1 尝试获取 ua 中记录 10 的lock x, gap before rec,insert intention,但被梗塞

2、提出问题

除了以上景象外,无奈从输入后果失去更多的信息,比方:

Q1: T1 为什么会持有 ua 中记录 10 的锁?

Q2: T1 既然持有了锁,为什么又会期待锁?

Q3: T2 持有和期待雷同的锁,到底是持有还是在期待?

Q4: 死锁到底是如何产生的?

为此,与研发同学沟通,理解死锁产生的业务场景,并对问题进行了再次复现。

三、重现问题

研发同学发现是在某业务的定时工作进行并发解决时触发,并很快在对应的开发环境复现了问题。问题复现后,同样在利用日志和 innodb status 输入看到对应日志,确认是同一问题。

倡议读者敌人思考 1 分钟,如何进一步剖析

1、尝试解决

本着解决问题优先的准则,在惟一索引 ua 并发时产生的,那是否能够将惟一索引改为一般索引?如果不能够,是否能够升高并发(或者间接改为单并发)?不过很快研发同学就进行了确认,uname 的惟一索引是外围框架依赖的,改不了!该性能的实时性要求很高,上线后业务量比拟大,不能升高或调小并发。既然无奈防止,那只能进一步剖析死锁产生的起因,并据此确认解决方案!

研发在复现问题后,除了能看到利用日志和 innodb status 输入,还是没有更多的信息。此外,研发是参考测试环境,造了一批数据,而后进行模仿复现的。即: 尽管能复现这个死锁,但无法回答最后提出的问题(Q1,Q2,Q3,Q4)。

2、跟踪死锁产生过程

随后找到 Percona 提供一篇文章(链接: How to deal with MySQL deadlocks),大抵对死锁的问题的剖析提供了思路: 以利用日志和 innodb status 提供的数据为根底,联合 events_statements_history、binlog(最好是 statement 格局)、慢查问日志(slow log)、个别日志(general log)进行剖析。

依据文章利用已有的性能(events_statements_history/slow log/general log),去找到数据库连贯运行过那些 SQL 语句。随后,总结了如下脚本:

-- 将 events_statements_history 中的启动工夫转换为规范工夫
create database IF NOT EXISTS perf_db;
use perf_db;
DELIMITER //
create function f_convert_timer_to_utc(pi_timer bigint) returns timestamp(6)
DETERMINISTIC
begin
    declare value_utc_time timestamp(6);
    select FROM_UNIXTIME((unix_timestamp(sysdate()) - variable_value) + pi_timer/1000000000000 )  from performance_schema.global_status where variable_name = 'Uptime' into value_utc_time;
    return value_utc_time;
end;
//
DELIMITER ;

--innodb status 输入中,死锁信息中 MySQL thread id,理论示意是 PROCESSLIST ID。执行语句找到 thread_id 与 PROCESSLIST_ID 的对应关系
select PROCESSLIST_ID,THREAD_ID,PROCESSLIST_INFO from performance_schema.threads where PROCESSLIST_ID in (8,10);

-- 找到上一步找到的线程 ID 找到运行过的 SQL 语句
select THREAD_ID,
 perf_db.f_convert_timer_to_utc(TIMER_START) run_start_time,
 perf_db.f_convert_timer_to_utc(TIMER_END) run_end_time,
 TIMER_WAIT/1000000000000 wait_time_s,
 'False' is_current,
 CURRENT_SCHEMA,
 SQL_TEXT
 from performance_schema.events_statements_history where thread_id=51
union 
select THREAD_ID,
 perf_db.f_convert_timer_to_utc(TIMER_START) run_start_time,
 perf_db.f_convert_timer_to_utc(TIMER_END) run_end_time,
 TIMER_WAIT/1000000000000 wait_time_s,
 'True' is_current,
 CURRENT_SCHEMA,
 SQL_TEXT
 from performance_schema.events_statements_current where thread_id=51
 and (THREAD_ID,EVENT_ID,END_EVENT_ID) not in (select THREAD_ID,EVENT_ID,END_EVENT_ID from performance_schema.events_statements_history)
order by run_start_time;

注:以上脚本中红色文字,须要依据理论状况替换。

整顿脚本后,研发同学再次尝试进行了复现死锁。查问失去如下后果:

select PROCESSLIST_ID,THREAD_ID,PROCESSLIST_INFO from performance_schema.threads where PROCESSLIST_ID in (8,10);

+----------------+-----------+------------------+
| PROCESSLIST_ID | THREAD_ID | PROCESSLIST_INFO |
+----------------+-----------+------------------+
|              8 |        49 | NULL             |  
|             10 |        51 | NULL             | 
+----------------+-----------+------------------+

thread_id=49 的 sql 运行状况:|        49 | 2023-03-25 02:15:59.173352 | 2023-03-25 02:15:59.173612 |      0.0003 | False      | testdb         | begin                                     |
|        49 | 2023-03-25 02:16:08.349311 | 2023-03-25 02:16:08.350678 |      0.0014 | False      | testdb         | insert into dl_tab(id,name) values(26,10) |
|        49 | 2023-03-25 02:16:26.824176 | 2023-03-25 02:16:26.826121 |      0.0019 | False      | testdb         | insert into dl_tab(id,name) values(40,8)  |
+-----------+----------------------------+----------------------------+-------------+------------+----------------+-------------------------------------------+

thread_id=51 的 sql 运行状况:|        51 | 2023-03-25 02:15:58.040749 | 2023-03-25 02:15:58.041057 |      0.0003 | False      | testdb         | begin                                     |
|        51 | 2023-03-25 02:16:17.408110 | 2023-03-25 02:16:26.828374 |      9.4203 | False      | testdb         | insert into dl_tab(id,name) values(30,10) |

梳理后果如下:

根据上述梳理后果,通过人工形式在开发环境执行上述 SQL 语句,再次发生死锁,且 innodb status 的死锁信息与测试环境基本相同。

至此,答复了最开始提出的问题 Q1:

Q1: T1 为什么会持有 ua 中记录 10 的锁?

答:因为该事务后面执行了语句如下语句,所以持有了记录 (26,10) 的锁:insert into dl_tab(id,name) values(26,10);

3、对于跟踪死锁额定的思考

从这个死锁的产生过程,刚好是 innodb status 死锁信息输入后果中的两个会话导致了死锁。但参加死锁的可能波及 3 个、4 个或者更多的事务,因而还有如下几个额定的问题:

Q5: 如果是 3 个或更多的事务参加死锁,如何跟踪?

Q6: 执行的 SQL 语句应该是导致死锁最间接的起因,其本质锁的是记录、锁类型及梗塞关系,如何查看?

Q7: 死锁产生后,因为 MySQL 死锁检测机制会主动发现死锁,并会筛选事务进行回退。事务被回退了之后,就毁坏了死锁的第一现场。除了 innodb status 提供的最近一次死锁信息外(特地是 8.0.18 之前不包含事务 1 持有的锁信息),再无其它可用的剖析数据。

综合以上 3 个问题,总结了如下补充计划,以采集相干的性能数据:

  • 针对 Q7:在测试环境长期敞开死锁检测,而后再次复现:
innodb_deadlock_detect = off
innodb_lock_wait_timeout = 10
innodb_rollback_on_timeout = on
  • 针对 Q5,Q6:联合 MySQL 已有的实时锁与锁期待性能数据,总结了如下脚本:
-- 创立工作目录
cd <path-to-dir>
mkdir deadlock_data
cd deadlock_data

-- 创立死锁数据保留表
mysql -uroot -S /tmp/mysql.sock
create database IF NOT EXISTS perf_db;
use perf_db
CREATE TABLE `tab_deadlock_info` (
  `id` int primary key auto_incrment,
  `curr_dt` datetime(6) NOT NULL,
  `thread_id` bigint unsigned DEFAULT NULL,
  `conn_id` bigint unsigned DEFAULT NULL,
  `trx_id` bigint unsigned DEFAULT NULL,
  `object_name` varchar(64) DEFAULT NULL,
  `INDEX_NAME` varchar(64) DEFAULT NULL,
  `lock_type` varchar(32) NOT NULL,
  `lock_mode` varchar(32) NOT NULL,
  `lock_status` varchar(32) NOT NULL,
  `LOCK_DATA` varchar(8192) CHARACTER SET utf8mb4 DEFAULT NULL,
  `blk_trx_id` bigint unsigned DEFAULT NULL,
  `blk_thd_id` bigint unsigned DEFAULT NULL,
  index idx_curr_dt(curr_dt)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4;

-- 查看以后存在的锁及锁梗塞信息
-- data_locks/data_lock_waits 自 MySQL 8.0.1 提供,之前版本查问 information_schema.innodb_locks/ information_schema.innodb_lock_waits 获取相似信息
vi save_lock_data.sql
insert into tab_deadlock_info(curr_dt,thread_id,conn_id,trx_id,object_name,index_name,
     lock_type,lock_mode,lock_status,lock_data,blk_trx_id,blk_thd_id)
select NOW(6) curr_dt,a.thread_id,b.PROCESSLIST_ID conn_id,
  ENGINE_TRANSACTION_ID trx_id, object_name,
  INDEX_NAME,lock_type,lock_mode,lock_status,LOCK_DATA,
  c.BLOCKING_ENGINE_TRANSACTION_ID blk_trx_id,
  c.BLOCKING_THREAD_ID blk_thd_id
from performance_schema.data_locks a left join performance_schema.threads b 
  on a.thread_id=b.thread_id
left join performance_schema.data_lock_waits c 
     on a.ENGINE_TRANSACTION_ID=c.REQUESTING_ENGINE_TRANSACTION_ID and a.thread_id=c.REQUESTING_THREAD_ID
where a.thread_id=b.thread_id order by thread_id,trx_id;

-- 查问脚本
mysql -uroot -S /tmp/mysql.sock perf_db -e "source save_lock_data.sql"

-- 定时查问脚本
vi run_save_lock.sh
while true
do
sleep 0.1 # 指定查问间隔时间,结合实际需要调整
mysql -uroot -S /tmp/mysql.sock perf_db -e "source save_lock_data.sql" 2>>run_save_lock.err
done

-- 执行查问
sh run_save_lock.sh

阐明:

A. 配置上述 innodb_deadlock_detect 参数敞开死锁检测,innodb status 将不在会持续输入最初 LATEST DETECTED DEADLOCK 信息;

B. 利用日志看到的告警为锁超时告警:Lock wait timeout exceeded; try restarting transaction。能够据此找到锁超时产生工夫。

再次复现后应用应用 tab_deadlock_info 查问锁数据如下:

同时,应用步骤 2)查问的语句信息如下:

综合上述查问后果,梳理失去如下后果:

再次梳理出了死锁的产生过程。

四、根因剖析

通过上述过程,能够看到死锁产生的过程,获取的锁及其属性信息。但要剖析出为什么会产生死锁,还须要联合 MySQL 的锁实现机制。因为以上死锁场景,波及惟一索引的插入实现逻辑,将联合源码进行解读。

1、单列惟一索引插入逻辑

下图中:

蓝色线示意 T1 第一次插入执行的逻辑;

紫色线示意 T2 第一次插入执行的逻辑;

彩色线示意 T1 第二次插入执行的逻辑;

与惟一索引插入记录相干锁操作,应用了红色短箭头标记;

竖线与红色短尖头穿插示意执行了函数,否则示意未执行。

2、最终死锁过程

以工夫维度,联合以上的 mysql 加锁逻辑进行剖析:

A. T1、T2 开启了一个事务,随后 T1 执行了插入 (26,10) 的 insert 语句

B. T2 执行了插入 (30,10) 的 insert 语句。进行唯一性抵触查看,尝试获取 LOCK_S | LOCK_ORDINARY[line 15]。那为什么看到时 LOCK S,是因为 LOCK_ORDINARY 对应的数字示意为 0,任何与之进行“与”运算都等于自身,所以看不出来:

C. 而后 T2 所在的连贯会将 T1 中的隐式锁转换为显示锁[line 17],此时 T1 将获取 LOCK_REC | LOCK_X | LOCK_REC_NOT_GAP,即看到的 Lock X, Rec_not_gap。因为是 T2 所在的线程为 T1 创立的锁,因而该锁对应的 thread_id 为 T2 的线程 ID,但 trx_id 为 T1 的事务 ID

D. 但因为 T1 的 LOCK X|LOCK_REC_NOT_GAP 与 T2 的 LOCK S| LOCK_ORDINARY 不兼容[line 23],因而 T2 被梗塞

E. 当 T2 被梗塞时,外部函数 add_to_waitq 在解决时,同样会记录创立一个锁,并设置属性 LOCK_S | LOCK_ORDINARY | LOCK_WAIT | LOCK_REC,以批示锁期待[line 24]。随后 T2 返回下层函数,以期待锁资源[line 38]

F. 随后,T1 又执行了 (40,8) 的 insert 语句。因为其插入的惟一索引值是 8(留神不是 10),因而不存在主键抵触,间接执行乐观插入操作[line 43]。

G. 执行乐观插入时,须要查看其它事务是否梗塞 insert 操作。其外围是获取待插入记录的下一个值[line 46-47](这里刚好是 10),并获取该记录上的所有锁,与须要增加的锁(LOCK_X | LOCK_GAP | LOCK_INSERT_INTENTION)判断是否存在抵触[line 51]。

H. 第 E 步 T2 持有了记录 10 的 LOCK_S | LOCK_ORDINARY | LOCK_WAIT | LOC

K_REC 锁与 T1 的 LOCK_X | LOCK_GAP | LOCK_INSERT_INTENTION 不兼容,因而 T1 被 T2 梗塞[line 51]

I. 死锁造成。

如需理解更多实现细节,大家能够联合源码进一步确认。

至此,答复了最开始提出的问题 Q2,Q3,Q4:

Q2: T1 既然持有了锁,为什么又会期待锁?

答:持有锁应该没有疑难,在剖析相似问题留神隐式锁转换为显示锁的机制(lock_rec_convert_impl_to_expl)。期待锁次要因为 T2 被梗塞后,会创立锁(LOCK_S | LOCK_ORDINARY | LOCK_WAIT | LOCK_REC)。而后 T1 在执行乐观插入时,须要遍历记录上存在的所有 > 锁进行锁抵触判断,因为锁模式不兼容,因而被梗塞

Q3: T2 持有和期待雷同的锁,到底是持有还是在期待?

答:尽管从 innodb status 看到 T2 持有和期待都是 lock s, next key lock。但实际上期待 lock s, next key lock;因为锁抵触,退出期待队列时会持有锁 LOCK_S | LOCK_ORDINARY | LOCK_WAIT | LOCK_REC

Q4: 死锁到底是如何产生的?

答:见以上剖析死锁过程剖析

五、解决问题

综合以上死锁产生的产生过程和起因,总结起因如下:

起因 1:次要研发适度依赖惟一索引,插入的数据不合乎惟一索引要求,须要进行唯一性抵触查看。

起因 2:批量插入的数据不是有序的。两种状况同时存在,导致死锁产生。

起因 2 在并发场景下,管制起来较为简单。起因 1 该场景为并发批量插入逻辑,能够在执行插入时,防止插入反复的 uname。随后,研发同学进行逻辑优化后,问题不再产生。

对于死锁问题,倡议联合业务状况尽量抉择 Read Committed 隔离级别,适当的缩小 Unique 索引。如的确产生死锁,读者敌人能够参考本次故障案例,正当利用性能数据来跟踪死锁问题,联合源码或者已有的案例剖析死锁根本原因和解决方案。

以上信息仅左右交换,作者程度无限,如有不足之处,欢送在评论区交换。

正文完
 0