Administrator
发布于 2020-08-14 / 1026 阅读
17

一次线上死锁:从 innodb status 到业务代码

告警: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;;:这一行是最有用的。hex 53534b553130303836 解码出来是 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 次/周
下单接口 TP99900ms165ms
库存事务平均耗时240ms8ms
死锁重试成功率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 到业务代码》这块我前前后后踩了不止一次。今天先写这些,后面想到新的再补。

参考