导语:在营销业务场景中,例如:短信推送、邮件推送、电销等,需要定期拉取大量用户用于上述营销场景。因此,我们设计研发了用户标签系统,系统中存在大量定时任务,涉及数据的拉取、存储、发送等环节,需要保证数据的幂等、一致性及上述流程的正常流转。
在数据持久化环节,为保证活动信息、任务实例等状态一致性,在最外层开启了事务。考虑到单次拉取的数据量过大,持久化数据使用无事务的方式批量提交,使用幂等保证异常情况下数据不会重复写入。但忽略了在任务实例较多的情况下,单次可能拉取很多任务实例,从而放大事务造成多个更新任务实例状态位于同一个事务内。这可能造成由于更新顺序不同引起的死锁。
本文总结了这次死锁排查的全过程,并分析了导致死锁的原因及解决方案。希望给大家提供一个死锁的排查及解决思路。
01.现象
某日线上出现大量的报警,提示有异常,先看下日志,日志中出现了大量的死锁,明显是由 DB 层面引起
org.springframework.dao.DeadlockLoserDataAccessException:
### Error updating database. Cause: com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
### The error may exist in com/atome/ops/mapper/CampaignJobInstanceMapper.java (best guess)
### The error may involve com.atome.ops.mapper.CampaignJobInstanceMapper.update-Inline
### The error occurred while setting parameters
### SQL: update `campaign_job_instance` SET `total_count`=?, `status`=?, `fetch_start_time`=?, `fetch_end_time`=?, `send_start_time`=?, `send_end_time`=?, `update_timestamp`=? where id=?
### Cause: com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
; Deadlock found when trying to get lock; try restarting transaction; nested exception is com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
复制代码
从报错日志可以看出,主键更新发生了死锁?引起这种现象的原因很多,结合我们的业务,我们分析一下。
02.Mysql 锁争用分析
1. 什么是死锁?
死锁是指两个或两个以上的进程在执行过程中,由于竞争资源或者由于彼此通信而造成的一种阻塞的现象。若无外力作用,它们都将无法推进下去。此时称系统处于死锁状态或系统产生了死锁,这些永远在互相等待的进程称为死锁进程。
在数据库 MySQL 的并发读写请求场景中。当两个及以上的事务,双方都在等待对方释放已经持有的锁或因为加锁顺序不一致造成循环等待锁资源,就会出现“死锁”。常见的报错信息为 Deadlock found when trying to get lock; try restarting transaction...
。
从死锁的定义来看,MySQL 出现死锁的几个要素为:
两个或者两个以上事务
每个事务都已经持有锁并且申请新的锁
锁资源同时只能被同一个事务持有或者不兼容
事务之间因为持有锁和申请锁导致彼此循环等待
在 Mysql 中死锁主要体现在 InnoDB 存储引擎,锁争用主要体现在 next-key lock、insert intention lock
2. next-key lock
next-key lock 由间隙锁(Gap Lock)和行锁组成,每个 next-key lock 是前开后闭区间。间隙锁之间不存在冲突关系,跟间隙锁存在冲突关系的,是“往这个间隙中插入一个记录”这个操作。
举例说明👇🏻
CREATE TABLE `t` (
`id` int(11) NOT NULL,
`c` int(11) DEFAULT NULL,
`d` int(11) DEFAULT NULL,
PRIMARY KEY (`id`),
KEY `c` (`c`)
) ENGINE=InnoDB;
insert into t values(0,0,0),(5,5,5),
(10,10,10),(15,15,15),(20,20,20),(25,25,25);
复制代码
上述语句执行结果如何?出现了死锁,为什么呢?
session A、session B 中select for update
由于 id=9 不存在,均加上了(5,10)的间隙锁,这也证明了间隙锁之间不存在冲突。接下来 A、B 都向这个间隙里插入数据,互相和对方持有的间隙锁冲突,相互等待形成死锁。如果开启了死锁检测,InnoDB 会马上发现死锁关系,让 A 中插入报错返回。
从以上例子也可以看出,由于间隙锁的引入,虽然解决了幻读,可也影响了数据库的并发度。如果实际业务场景不需要保证可重复读,就可以考虑使用读已提交,同时 binlog_format=row,保证主从同步的一致性。
加锁规则:两个原则、两个优化、一个 bug
原则 1:加锁的基本单位是 next-key lock,前开后闭区间
原则 2:查找过程中访问到的对象才会加锁
优化 1:索引上的等值查询,给唯一索引加锁的时候,匹配上数据,next-key lock 退化为行锁
优化 2:索引上的等值查询,向右遍历时且最后一个值不满足等值条件的时候,next-key lock 退化为间隙锁
一个 bug:唯一索引上的范围查询会访问到不满足条件的第一个值为止
以上规则,其实可以理解为数据查找过程中,扫描到的对象应该加锁,排除逻辑上明显不需要加锁的对象,即为加锁范围
重点:
加锁是分步进行的,例如:c>=10 and c<=11
,分解为 c=10、c>10 and c<11、c=11 依次进行锁申请
间隙由右边的间隙记录,这也导致了不同方向上扫描加锁范围不一样
从扫描到的第一个记录上作为起点,例如:普通索引 c 取值为[0,5,10,15,20],c>10 和 c>=10 其分别第一个扫描到的数为 15、10,因此第一个间隙锁为(10,15]、(5,10]
3.insert intention lock
插入意向锁,仅用于 insert 语句,表明将在某间隙插入记录,与间隙锁互斥关系如下:
间隙锁之间不存在互斥关系(X、S 表示是什么语句导致的间隙锁)
间隙锁可以堵塞区间内的插入意向锁,但插入意向锁不会堵塞后续的间隙锁
唯一键冲突,如果是主键加记录锁,如果是唯一索引加 next-key lock
插入意向锁实验验证
mysql> CREATE TABLE `t` (
`id` int(11) NOT NULL,
`c` int(11) DEFAULT NULL,
`d` int(11) DEFAULT NULL,
PRIMARY KEY (`id`),
KEY `c` (`c`)
) ENGINE=InnoDB;
mysql> insert into t values(0,0,0),(5,5,5),
(10,10,10),(15,15,15),(20,20,20),(25,25,25);
-- 开启事务A
mysql> begin;
/**
在事务A中执行修改语句,id=7不存在,添加(5,10)的间隙锁,LOCK_MODE=X,GAP LOCK_DATA=10可以验证两个观点:
1、间隙锁是加在右边间隙上的
2、此处X并不代表10上加行锁,仅代表什么语句造成的,若改为select * from t where id=7 lock in share mode,LOCK_MODE就变为S,GAP
**/
mysql> update t set d=d+1 where id=7;
-- 在事务B中插入id=6的数据,需要申请插入意向锁,进入堵塞状态
mysql> insert into t values(6,6,6);
/**
事务A中已经添加了间隙锁,相同间隙的插入意向锁堵塞,LOCK_MODE=X,GAP,INSERT_INTENTION,LOCK_STATUS=WAITING
v8.0.11时,LOCK_MODE=X,GAP,INSERT_INTENTION标识是高版本新加的(此处使用的是8.0.21),插入意向锁是一种特殊的间隙锁
**/
mysql> select THREAD_ID,OBJECT_SCHEMA,OBJECT_NAME,INDEX_NAME,LOCK_TYPE,LOCK_MODE,LOCK_STATUS,LOCK_DATA
from performance_schema.data_locks;
+-----------+---------------+-------------+------------+-----------+------------------------+-------------+-----------+
| THREAD_ID | OBJECT_SCHEMA | OBJECT_NAME | INDEX_NAME | LOCK_TYPE | LOCK_MODE | LOCK_STATUS | LOCK_DATA |
+-----------+---------------+-------------+------------+-----------+------------------------+-------------+-----------+
| 54 | demo | t | NULL | TABLE | IX | GRANTED | NULL |
| 54 | demo | t | PRIMARY | RECORD | X,GAP | GRANTED | 10 |
| 53 | demo | t | NULL | TABLE | IX | GRANTED | NULL |
| 53 | demo | t | PRIMARY | RECORD | X,GAP,INSERT_INTENTION | WAITING | 10 |
+-----------+---------------+-------------+------------+-----------+------------------------+-------------+-----------+
-- 开启事务C
mysql> begin;
-- 在事务C中插入id=16的数据,由于该间隙上没有间隙锁,申请插入意向锁成功
mysql> insert into t values(16,16,16);
/**
查询当前加锁情况,并没有发现插入意向锁,为什么?
插入意向锁是为了配合间隙锁解决幻读问题,在有间隙锁的情况下进行堵塞。此时没有间隙锁,不需要堵塞,所以就不用加插入意向锁吗?
但其他事务中相同行插入会产生冲突,说明这里还是有其他约束的,只是不用堵塞的插入意向锁转换成另外一种约束了
**/
mysql> select THREAD_ID,OBJECT_SCHEMA,OBJECT_NAME,INDEX_NAME,LOCK_TYPE,LOCK_MODE,LOCK_STATUS,LOCK_DATA
from performance_schema.data_locks;
+-----------+---------------+-------------+------------+-----------+-----------+-------------+-----------+
| THREAD_ID | OBJECT_SCHEMA | OBJECT_NAME | INDEX_NAME | LOCK_TYPE | LOCK_MODE | LOCK_STATUS | LOCK_DATA |
+-----------+---------------+-------------+------------+-----------+-----------+-------------+-----------+
| 53 | demo | t | NULL | TABLE | IX | GRANTED | NULL |
+-----------+---------------+-------------+------------+-----------+-----------+-------------+-----------+
/**
证明其他约束的存在,新启一个事务,同样执行insert into t values(16,16,16),可以看到申请S锁堵塞,正常上一个事务中的插入有其他约束
这里需要进行唯一约束验证,获取id=16的读锁
**/
mysql> select THREAD_ID,OBJECT_SCHEMA,OBJECT_NAME,INDEX_NAME,LOCK_TYPE,LOCK_MODE,LOCK_STATUS,LOCK_DATA
from performance_schema.data_locks;
+-----------+---------------+-------------+------------+-----------+---------------+-------------+-----------+
| THREAD_ID | OBJECT_SCHEMA | OBJECT_NAME | INDEX_NAME | LOCK_TYPE | LOCK_MODE | LOCK_STATUS | LOCK_DATA |
+-----------+---------------+-------------+------------+-----------+---------------+-------------+-----------+
| 53 | demo | t | NULL | TABLE | IX | GRANTED | NULL |
| 56 | demo | t | NULL | TABLE | IX | GRANTED | NULL |
| 56 | demo | t | PRIMARY | RECORD | X,REC_NOT_GAP | GRANTED | 16 |
| 56 | demo | t | PRIMARY | RECORD | S,REC_NOT_GAP | WAITING | 16 |
+-----------+---------------+-------------+------------+-----------+---------------+-------------+-----------+
-- 开启事务D
mysql> begin;
-- 在事务D中插入id=10,
mysql> insert into t values(10,10,10);
1062 - Duplicate entry '10' for key 'PRIMARY'
-- 在事务E中插入id=9
mysql> insert into t values(9,9,9);
(blocked)
/**V8.0.11
查看当前加锁情况,事务D插入语句检测到唯一冲突后在id=10上加了一个S锁
事务E中插入id=9,等待插入意向锁,没有间隙锁冲突,为什么会堵塞呢?
唯一键冲突加的应该不是一个记录S锁,应该是一个next-key lock (5,10],因为已经存在间隙锁,所以插入意向锁才会堵塞
这是MySQL的一个bug,在V8.0.16已经修复,事务E中插入不会堵塞(主键唯一冲突就是一个单纯的记录锁)
https://bugs.mysql.com/bug.php?id=93806
**/
mysql> select THREAD_ID,OBJECT_SCHEMA,OBJECT_NAME,INDEX_NAME,LOCK_TYPE,LOCK_MODE,LOCK_STATUS,LOCK_DATA
from performance_schema.data_locks;
+--------+-----------+---------------+-------------+------------+-----------+-----------+-------------+-----------+
| ENGINE | THREAD_ID | OBJECT_SCHEMA | OBJECT_NAME | INDEX_NAME | LOCK_TYPE | LOCK_MODE | LOCK_STATUS | LOCK_DATA |
+--------+-----------+---------------+-------------+------------+-----------+-----------+-------------+-----------+
| INNODB | 109 | demo | t | NULL | TABLE | IX | GRANTED | NULL |
| INNODB | 109 | demo | t | PRIMARY | RECORD | S | GRANTED | 10 |
| INNODB | 108 | demo | t | NULL | TABLE | IX | GRANTED | NULL |
| INNODB | 108 | demo | t | PRIMARY | RECORD | X,GAP | WAITING | 10 |
+--------+-----------+---------------+-------------+------------+-----------+-----------+-------------+-----------+
复制代码
03.原因及解决
1. 死锁日志明细
通过执行show engine innodb status
查看最近一次的死锁日志,如下所示:
## 执行以下语句查看最近一次死锁日志
show engine innodb status;
...
------------------------
LATEST DETECTED DEADLOCK
------------------------
2022-02-07 21:00:00 0x7f3972be1700
*** (1) TRANSACTION:
TRANSACTION 401368548, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 4 lock struct(s), heap size 1136, 4 row lock(s), undo log entries 3
MySQL thread id 24621163, OS thread handle 139885409634048, query id 1074586194 172.21.32.245 root Updating
update `campaign_job_instance`
SET `total_count`=6,
`status`='SENDING',
`fetch_start_time`=1644238560063,
`fetch_end_time`=1644238560115,
`send_start_time`=1644238800550,
`send_end_time`=null,
`update_timestamp`=1644238800550
where id=5193
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 10003 page no 263 n bits 104 index PRIMARY of table `user_label`.`campaign_job_instance` trx id 401368548 lock_mode X locks rec but not gap waiting
Record lock, heap no 35 PHYSICAL RECORD: n_fields 17; compact format; info bits 0
0: len 4; hex 00001449; asc I;;
1: len 6; hex 000017ec6739; asc g9;;
2: len 7; hex 390002800f1934; asc 9 4;;
3: len 28; hex 6a6f622d363166653865333464636531613630303031346636333166; asc job-61fe8e34dce1a600014f631f;;
4: len 24; hex 363230313136653033333863656530303031326637346337; asc 620116e0338cee00012f74c7;;
5: len 30; hex 3631666538653334646365316136303030313466363331642d3230323230; asc 61fe8e34dce1a600014f631d-20220; (total 37 bytes);
6: len 3; hex 534d53; asc SMS;;
7: len 24; hex 363166653865333464636531613630303031346636333164; asc 61fe8e34dce1a600014f631d;;
8: len 30; hex 66353464623661372d336263662d346361312d613630302d643337616234; asc f54db6a7-3bcf-4ca1-a600-d37ab4; (total 36 bytes);
9: len 4; hex 53454e54; asc SENT;;
...
*** (2) TRANSACTION:
TRANSACTION 401368889, ACTIVE 0 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 24621104, OS thread handle 139884714923776, query id 1074586215 172.21.32.245 root Updating
update `campaign_job_instance`
SET `total_count`=6,
`status`='SENT',
`fetch_start_time`=1644238560026,
`fetch_end_time`=1644238560120,
`send_start_time`=1644238800280,
`send_end_time`=1644238800554,
`update_timestamp`=1644238800554
where id=5192
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 10003 page no 263 n bits 104 index PRIMARY of table `user_label`.`campaign_job_instance` trx id 401368889 lock_mode X locks rec but not gap
Record lock, heap no 35 PHYSICAL RECORD: n_fields 17; compact format; info bits 0
0: len 4; hex 00001449; asc I;;
1: len 6; hex 000017ec6739; asc g9;;
2: len 7; hex 390002800f1934; asc 9 4;;
3: len 28; hex 6a6f622d363166653865333464636531613630303031346636333166; asc job-61fe8e34dce1a600014f631f;;
4: len 24; hex 363230313136653033333863656530303031326637346337; asc 620116e0338cee00012f74c7;;
5: len 30; hex 3631666538653334646365316136303030313466363331642d3230323230; asc 61fe8e34dce1a600014f631d-20220; (total 37 bytes);
6: len 3; hex 534d53; asc SMS;;
7: len 24; hex 363166653865333464636531613630303031346636333164; asc 61fe8e34dce1a600014f631d;;
8: len 30; hex 66353464623661372d336263662d346361312d613630302d643337616234; asc f54db6a7-3bcf-4ca1-a600-d37ab4; (total 36 bytes);
9: len 4; hex 53454e54; asc SENT;;
...
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 10003 page no 263 n bits 104 index PRIMARY of table `user_label`.`campaign_job_instance` trx id 401368889 lock_mode X locks rec but not gap waiting
Record lock, heap no 23 PHYSICAL RECORD: n_fields 17; compact format; info bits 0
0: len 4; hex 00001448; asc H;;
1: len 6; hex 000017ec65e4; asc e ;;
2: len 7; hex 0e000002a31da0; asc ;;
3: len 28; hex 6a6f622d363230303832346464636531613630303031346636333261; asc job-6200824ddce1a600014f632a;;
4: len 24; hex 363230313136653033333863656530303031326637346334; asc 620116e0338cee00012f74c4;;
5: len 30; hex 3632303038323464646365316136303030313466363332382d3230323230; asc 6200824ddce1a600014f6328-20220; (total 37 bytes);
6: len 3; hex 534d53; asc SMS;;
7: len 24; hex 363230303832346464636531613630303031346636333238; asc 6200824ddce1a600014f6328;;
8: len 30; hex 33333839633535662d663262612d346630392d393432632d353839633865; asc 3389c55f-f2ba-4f09-942c-589c8e; (total 36 bytes);
9: len 7; hex 53454e44494e47; asc SENDING;;
...
*** WE ROLL BACK TRANSACTION (2)
------------
TRANSACTIONS
------------
...
复制代码
参考:mysql之show engine innodb status解读
从上述日志可以看出以下几点:
锁争用体现在主键行锁(RECORD LOCKS... index PRIMARY...lock_mode X locks rec but not gap waiting
)
事务 1 更新 id=5193 的数据,且等待其行锁
事务 2 更新 id=5192 的数据,且等待其行锁
事务 2 已持有 id=5193 的行锁
从日志中分析出的加锁情况可以直接看出,事务 2 持有了事务 1 中需要的行锁 id=5193。既然产生死锁,那么事务 1 中一定持有事务 2 中需要的行锁 id=5192,这里为什么没有输出事务 1 中持有锁情况呢?
但是从LOCK WAIT 4 lock struct(s), heap size 1136, 4 row lock(s), undo log entries 3
还是可以看出事务 1 中持有其他行锁。
另外,单纯上述两条语句,不可能产生上述加锁情况。因此,不要陷入一个误区:锁定的数据行并不一定是由锁冲突的 sql 语句引起的,应该关注同一事务中是否有其它语句加锁。
2. 代码分析
通过上述日志分析,基本上可以直接定位到业务代码中锁冲突发生的位置
/**
* 读取文件写入数据明细表,最后通过主键更新campaign_job_instance
*/
class SaveUserJob implements SimpleJob {
@Autowired
@Transactional
CampaignJobInstanceService campaignJobInstanceService
@Override
void execute(ShardingContext shardingContext) {
log.info("save user:${JsonUtil.toString(shardingContext)}")
List<CampaignJobInstance> jobInstances = campaignJobInstanceService.findByStatus(CampaignJobInstanceStatusEnum.SAVING)
jobInstances.each { jobInstance ->
...
updateById(jobInstance)
...
}
}
}
/**
* 发送SaveUserJob写入的数据明细,最后主键更新campaign_job_instance
*/
class SendJob implements DataflowJob<CampaignUserLog> {
...
@Override
@Transactional
void processData(ShardingContext shardingContext, List<CampaignUserLog> logs) {
connectorExecuteService.execute(logs.findAll { it.status == CampaignUserJobStatusEnum.SENDING })
logs.groupBy { it.jobInstanceId }.each {
CampaignJobInstance jobInstance = findByInstanceId(it.key)
...
updateById(jobInstance)
}
}
...
}
复制代码
SaveUserJob、SendJob 中均涉及到遍历主键更新 campaign_job_instance,且均开启事务。造成死锁的原因就很清楚了,两个事务中更新顺序不同带来的加锁顺序不同,造成相互持有对方需要的锁,从而死锁。
但是为什么之前测试时没有出发?
3.解决方案
知道了死锁发生的原因,解决方案就很简单了,减小锁粒度即可。
class SaveUserJob implements SimpleJob {
@Autowired
CampaignJobInstanceService campaignJobInstanceService
@Override
// 外层仅查询,去除事务
void execute(ShardingContext shardingContext) {
log.info("save user:${JsonUtil.toString(shardingContext)}")
List<CampaignJobInstance> jobInstances = campaignJobInstanceService.findByStatus(CampaignJobInstanceStatusEnum.SAVING)
jobInstances.each { jobInstance ->
// 抽取到service层,加上事务
campaignJobInstanceService.saveUser(jobInstance)
}
}
}
class SendJob implements DataflowJob<CampaignUserLog> {
...
@Override
// 外层仅查询,去除事务
void processData(ShardingContext shardingContext, List<CampaignUserLog> logs) {
...
logs.groupBy { it.jobInstanceId }.each {
...
// 抽取到service层,加上事务
CampaignJobInstance jobInstance = findByInstanceId(it.key)
campaignJobInstanceService.checkJobInstance(jobInstance)
}
}
...
}
复制代码
4.对业务的影响
由于开启了死锁检测,数据库会自动回滚其中一个事务,同时方案设计考虑了状态补偿机制,并未对业务数据造成影响。但需要以此为鉴,在今后的方案设计与实现中尽量避免此类问题的产生。
04.TODO
由于之前表拆的比较细,且此处有较强的数据一致性要求,因此使用了事务,但是会影响性能。后面会对该处做重构。尽量使用无锁+并行的方式来提高吞吐量。
关于领创集团
(Advance Intelligence Group)
领创集团成立于 2016 年,致力于通过科技创新的本地化应用,改造和重塑金融和零售行业,以多元化的业务布局打造一个服务于消费者、企业和商户的生态圈。集团旗下包含企业业务和消费者业务两大板块,企业业务包含 ADVANCE.AI 和 Ginee,分别为银行、金融、金融科技、零售和电商行业客户提供基于 AI 技术的数字身份验证、风险管理产品和全渠道电商服务解决方案;消费者业务 Atome Financial 包括亚洲领先的先享后付平台 Atome 和数字金融服务。2021 年 9 月,领创集团宣布完成超 4 亿美元 D 轮融资,融资完成后领创集团估值已超 20 亿美元,成为新加坡最大的独立科技创业公司之一。
往期回顾 BREAK AWAY
企业级 APIs 安全实践指南 (建议初中级工程师收藏)
Cypress UI 自动化测试框架
▼ 如果觉得这篇内容对你有所帮助,有所启发,欢迎点赞收藏:
1、点赞、关注领创集团,获取最新技术分享和公司动态。
2、关注我们的公众号 &知乎号「领创集团 Advance Group」,了解更多企业动态。
评论