告警:Deadlock found when trying to get lock
八月中旬的一个晚上,钉钉群开始刷告警。库存服务的日志里出现了这个:
2020-08-13 21:14:32.881 ERROR [http-nio-8080-exec-42] o.s.i.d.i.InventoryMapper.deductBatch :
### Error updating database. Cause: com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException:
Deadlock found when trying to get lock; try restarting transaction
### The error may involve com.xxx.mapper.InventoryMapper.deductBatch-Inline
### The error occurred while setting parameters
### SQL: UPDATE t_inventory SET stock = stock - ? WHERE sku_id = ? AND stock >= ?
### Cause: com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException:
Deadlock found when trying to get lock; try restarting transaction
频率不算高,一小时 20~30 次,但每次都意味着一笔订单扣库存失败。我们当时的处理是简单地重试了两次,所以没造成资损,但重试耗时让下单接口 TP99 从 180ms 涨到了 900ms。
第一步:拿到死锁日志
MySQL 8.0 用这条命令看最近一次死锁:
SHOW ENGINE INNODB STATUS\G
输出里找到 LATEST DETECTED DEADLOCK 这一段:
------------------------
LATEST DETECTED DEADLOCK
------------------------
2020-08-13 21:14:32 0x7f8e4c0d9700
*** (1) TRANSACTION:
TRANSACTION 4218934, ACTIVE 0.021 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 4 lock struct(s), heap size 1136, 3 row lock(s), undo log entries 2
MySQL thread id 88213, OS thread handle 140243..., query id 39844122 10.20.3.11 appuser updating
UPDATE t_inventory SET stock = stock - 2 WHERE sku_id = 'SKU10086' AND stock >= 2
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 342 page no 4 n bits 80 index uk_sku of table `shop`.`t_inventory` trx id 4218934
lock_mode X locks rec but not gap waiting
Record lock, heap no 5 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 8; hex 53534b553130303836; asc SKU10086;;
1: len 8; hex 80000000000000ca; asc ;;
*** (2) TRANSACTION:
TRANSACTION 4218936, ACTIVE 0.018 sec starting index read
mysql tables in use 1, locked 1
4 lock struct(s), heap size 1136, 3 row lock(s), undo log entries 1
UPDATE t_inventory SET stock = stock - 1 WHERE sku_id = 'SKU10001' AND stock >= 1
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 342 page no 4 n bits 80 index uk_sku ... lock_mode X locks rec but not gap
Record lock, heap no 5 ... asc SKU10086;;
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS ... index uk_sku ... lock_mode X locks rec but not gap waiting
Record lock, heap no 3 ... asc SKU10001;;
*** WE ROLL BACK TRANSACTION (2)
解读这段日志的几个关键点
第一次看这个输出是一脸懵的,我总结一下要看懂它需要抓住的东西:
(1) TRANSACTION和(2) TRANSACTION:两个互相等待的事务。MySQL 会选择 undo log 量小的那个回滚(这里WE ROLL BACK TRANSACTION (2),因为它只有 1 条 undo,而 (1) 有 2 条)。lock_mode X locks rec but not gap:X 锁(排他锁),rec but not gap表示是记录锁而非间隙锁。说明这条 UPDATE 命中了唯一索引uk_sku,且是等值匹配,所以只锁这一行。如果看到locks gap before rec或者next key,那就是间隙锁,问题会不一样。index uk_sku:锁在哪个索引上。如果这里显示PRIMARY或者GEN_CLUST_INDEX,说明走的是聚簇索引,通常是没建索引导致锁范围扩大。asc SKU10086;;:这一行是最有用的。hex53534b553130303836解码出来是SKU10086,就是被锁的那条记录的索引键值。我一开始不知道这段是 hex,看着一堆十六进制发呆,后来才知道右边那个asc后面跟的就是 ASCII 解码结果。
把信息拼起来:
- 事务 1 先更新了 SKU10001,然后要更新 SKU10086,在等 SKU10086 的锁。
- 事务 2 先更新了 SKU10086(已持有锁),然后要更新 SKU10001,在等 SKU10001 的锁。
- 典型的交叉加锁形成环路。
根因:批量更新的顺序不受控
找到对应的业务代码,是一个批量扣库存的方法:
@Transactional(rollbackFor = Exception.class)
public void deductBatch(List<DeductItem> items) {
for (DeductItem item : items) {
int rows = inventoryMapper.deduct(item.getSkuId(), item.getQuantity());
if (rows == 0) {
throw new BizException("库存不足, skuId=" + item.getSkuId());
}
}
}
<update id="deduct">
UPDATE t_inventory
SET stock = stock - #{quantity}, update_time = NOW()
WHERE sku_id = #{skuId}
AND stock >= #{quantity}
</update>
问题在于 items 这个 List 的顺序。一个订单里的多个商品,顺序来自购物车,而购物车是按加入时间排的。用户 A 的购物车是 [SKU10001, SKU10086],用户 B 的是 [SKU10086, SKU10001]。两个订单同时下单,就形成了上面的死锁。
我用两个 MySQL 会话在本地复现过,非常稳定:
-- 会话 1
START TRANSACTION;
UPDATE t_inventory SET stock = stock - 1 WHERE sku_id = 'SKU10001' AND stock >= 1; -- 成功
-- 会话 2
START TRANSACTION;
UPDATE t_inventory SET stock = stock - 1 WHERE sku_id = 'SKU10086' AND stock >= 1; -- 成功
-- 回到会话 1
UPDATE t_inventory SET stock = stock - 1 WHERE sku_id = 'SKU10086' AND stock >= 1; -- 阻塞
-- 会话 2
UPDATE t_inventory SET stock = stock - 1 WHERE sku_id = 'SKU10001' AND stock >= 1; -- 死锁!
ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction
解决方案一:固定加锁顺序(最根本)
思路很简单:如果所有事务都按同一个顺序加锁,就不可能形成环路。在批量操作前按 skuId 排个序:
@Transactional(rollbackFor = Exception.class)
public void deductBatch(List<DeductItem> items) {
List<DeductItem> sorted = items.stream()
.sorted(Comparator.comparing(DeductItem::getSkuId))
.collect(Collectors.toList());
for (DeductItem item : sorted) {
int rows = inventoryMapper.deduct(item.getSkuId(), item.getQuantity());
if (rows == 0) {
throw new BizException("库存不足, skuId=" + item.getSkuId());
}
}
}
注意排序要在进入循环之前做,而且排序的键必须和数据库加锁的键一致(这里是 sku_id,命中唯一索引 uk_sku)。如果加锁走的是主键,那就得按主键排。
另外要合并同一 sku 的多次扣减。如果一个订单里同一个商品出现两次(用户分两次加入购物车),排序后它们是相邻的,但还是会锁两次,可以合并成一条:
Map<String, Integer> merged = items.stream()
.collect(Collectors.toMap(DeductItem::getSkuId, DeductItem::getQuantity, Integer::sum));
new TreeMap<>(merged).forEach((skuId, qty) -> {
if (inventoryMapper.deduct(skuId, qty) == 0) {
throw new BizException("库存不足, skuId=" + skuId);
}
});
TreeMap 天然按 key 有序,省一次显式排序。
解决方案二:拆大事务,缩短持锁时间
排序解决了交叉加锁,但还有一个隐患:事务越长,锁持有的时间越长,冲突概率越高。
我们原来的 deductBatch 外面还包了一层下单逻辑,整个事务里有:查商品 → 查优惠券 → 算价 → 扣库存 → 生成订单 → 写订单明细 → 发 MQ。整个事务平均耗时 240ms,其中扣库存只占 5ms,剩下 235ms 里锁一直挂在手上。
改造后的流程:把库存扣减单独提一个事务,放在整个下单流程的靠后位置,并且尽量缩短它自己的范围。
// 事务边界缩小到只有库存操作
@Transactional(propagation = Propagation.REQUIRES_NEW, rollbackFor = Exception.class)
public void deductInNewTx(List<DeductItem> items) {
new TreeMap<>(mergeBySku(items)).forEach((skuId, qty) -> {
if (inventoryMapper.deduct(skuId, qty) == 0) {
throw new BizException("库存不足, skuId=" + skuId);
}
});
}
这个事务的平均耗时从 240ms 降到 8ms。持锁时间缩短两个数量级,冲突概率自然跟着降。
解决方案三:重试机制(兜底,必须有)
死锁无法 100% 避免,业务层必须有重试。但要重试得注意:MySQL 回滚的是整个事务,所以重试必须在事务外面。
public void deductWithRetry(List<DeductItem> items, int maxRetry) {
for (int i = 0; i < maxRetry; i++) {
try {
deductInNewTx(items);
return;
} catch (DeadlockLoserDataAccessException e) {
if (i == maxRetry - 1) throw e;
// 随机退避,避免多个线程同时重试又撞在一起
int backoff = 20 + ThreadLocalRandom.current().nextInt(80);
LockSupport.parkNanos(TimeUnit.MILLISECONDS.toNanos(backoff));
log.warn("扣库存遇到死锁,第 {} 次重试, backoff={}ms", i + 1, backoff);
}
}
}
重试的退避时间一定要随机。我们第一版用的是固定 50ms,结果两个冲突的线程每次都是同时重试、再次撞上,重试 3 次全失败。加了随机抖动之后,重试成功率接近 100%。
改造效果
| 指标 | 改造前 | 改造后 |
|---|---|---|
| 死锁次数 | 20~30 次/小时 | 0~2 次/周 |
| 下单接口 TP99 | 900ms | 165ms |
| 库存事务平均耗时 | 240ms | 8ms |
| 死锁重试成功率 | 41% | 99.6% |
剩下的偶发死锁来自另一个场景:运营后台的调整库存功能和前台下单撞在一起。那个我们加了分布式锁(Redisson,按 skuId 粒度)来串行化,但那是另一个话题了。
顺手记一下排查的常用命令
-- 最近的死锁(只保留最后一条,8.0 要看 error log)
SHOW ENGINE INNODB STATUS\G
-- 8.0 推荐:把死锁记进错误日志,不会丢
SET GLOBAL innodb_print_all_deadlocks = ON;
-- 查看当前锁等待
SELECT * FROM performance_schema.data_lock_waits;
SELECT * FROM performance_schema.data_locks;
-- 查看未提交的长事务
SELECT trx_id, trx_started, trx_state, trx_rows_locked, trx_query
FROM information_schema.innodb_trx
ORDER BY trx_started LIMIT 10;
innodb_print_all_deadlocks 这个一定要开。生产上死锁可能一分钟发生好几次,SHOW ENGINE INNODB STATUS 只能看到最后一次,等你登上去早就覆盖了。
先到这
《一次线上死锁:从 innodb status 到业务代码》这块我前前后后踩了不止一次。今天先写这些,后面想到新的再补。