Administrator
发布于 2019-07-08 / 667 阅读
15

一次线上死锁排查:jstack 定位与修复

批量扣款任务卡死后,单笔扣款接口也全挂了

7 月 5 号早上 9 点 12 分,监控开始告警:/api/deduct 接口响应时间从 60 毫秒飙到 30 秒全部超时。同时 DBA 在群里说,account 表上有锁等待,已经持续 4 分钟。

第一反应是数据库慢查询。但登上机器看,应用这边 CPU 只有 6%,Tomcat 的 200 个线程里 187 个处于 BLOCKED 状态。这不像慢查询,像死锁。

jstack 直接给出了答案

抓一份线程栈:

$ jps -l
2831 /app/settle-service.jar

$ jstack -l 2831 > /tmp/stack.txt
$ tail -40 /tmp/stack.txt

jstack 自己就带死锁检测,输出到文件末尾:

Found one Java-level deadlock:
=============================
"batch-deduct-thread-2":
  waiting to lock monitor 0x00007f9a34003e58 (object 0x00000006c1a2b3f0, a com.xxx.settle.AccountLockManager),
  which is held by "http-nio-8080-exec-77"
"http-nio-8080-exec-77":
  waiting to lock monitor 0x00007f9a34005f18 (object 0x00000006c1a2b410, a com.xxx.settle.AccountLockManager),
  which is held by "batch-deduct-thread-2"

Java stack information for the threads listed above:
===================================================
"batch-deduct-thread-2" #92 prio=5 os_prio=0 tid=0x00007f9a1c2e0000 nid=0x8f21 waiting for monitor entry
   java.lang.Thread.State: BLOCKED (on object monitor)
    at com.xxx.settle.AccountLockManager.lock(AccountLockManager.java:44)
    - waiting to lock <0x00000006c1a2b3f0> (a com.xxx.settle.AccountLockManager)
    at com.xxx.settle.BatchDeductTask.process(BatchDeductTask.java:88)
    ...

"http-nio-8080-exec-77" #181 daemon prio=5 os_prio=0 tid=0x00007f9a1d104000 nid=0x3a7b waiting for monitor entry
   java.lang.Thread.State: BLOCKED (on object monitor)
    at com.xxx.settle.AccountLockManager.lock(AccountLockManager.java:44)
    - waiting to lock <0x00000006c1a2b410> (a com.xxx.settle.AccountLockManager)
    at com.xxx.settle.DeductService.deduct(DeductService.java:63)
    at com.xxx.settle.DeductController.deduct(DeductController.java:31)
    ...

Found 1 deadlock.

-l 参数是必须的,不加它只打印线程的锁信息,不会做死锁检测分析。

死锁确实存在,但只有 2 个线程互相锁。那另外 185 个 BLOCKED 的线程是怎么回事?它们是被这两个线程连带堵住的——批量任务占着连接池的连接,接口线程拿不到连接,全堵在 DruidDataSource.getConnection 上。所以现象是"接口全挂",根因只有两个线程。

锁顺序不一致

出问题的 AccountLockManager 是我写的,为了在应用层保护账户余额,避免并发扣款。它给每个账户分配一把锁:

@Component
public class AccountLockManager {
    private final ConcurrentHashMap<Long, ReentrantLock> locks = new ConcurrentHashMap<>();

    public ReentrantLock getLock(Long accountId) {
        return locks.computeIfAbsent(accountId, k -> new ReentrantLock());
    }
}

然后业务代码这么用:

// 单笔扣款:先锁付款方,再锁收款方
public void deduct(Long fromId, Long toId, BigDecimal amount) {
    ReentrantLock fromLock = lockManager.getLock(fromId);
    ReentrantLock toLock = lockManager.getLock(toId);
    fromLock.lock();
    toLock.lock();
    try {
        accountMapper.deduct(fromId, amount);
        accountMapper.add(toId, amount);
    } finally {
        toLock.unlock();
        fromLock.unlock();
    }
}

// 批量任务:遍历账户列表,逐个加锁
public void process(List<TransferBill> bills) {
    // bills 里 fromId 和 toId 的顺序,取决于运营上传的 Excel
    for (TransferBill bill : bills) {
        ReentrantLock fromLock = lockManager.getLock(bill.getFromId());
        ReentrantLock toLock = lockManager.getLock(bill.getToId());
        fromLock.lock();
        toLock.lock();
        ...
    }
}

看起来两边都是"先 from 后 to",顺序一致。问题在于批量任务处理的是转账,而单笔接口处理的是扣款,两个语义的 from/to 是反的。运营上传的那批 Excel 里,A 账户作为收款方出现在第 3 行、作为付款方出现在第 17 行,批量任务就先锁了 to(A) 再锁 from(B);同时单笔接口来了一笔 B→A 的扣款,先锁 from(B) 再锁 to(A)。

两边拿着各自的锁等对方,经典死锁。

修复方式很简单:加锁前对 accountId 排序,保证全局的加锁顺序一致。

public void transfer(Long id1, Long id2, TransferCallback callback) {
    // 按 id 大小排序,无论调用方怎么传,加锁顺序都一样
    long first = Math.min(id1, id2);
    long second = Math.max(id1, id2);

    ReentrantLock lock1 = lockManager.getLock(first);
    ReentrantLock lock2 = lockManager.getLock(second);

    lock1.lock();
    try {
        if (first != second) {
            lock2.lock();
        }
        try {
            callback.doTransfer();
        } finally {
            if (first != second) {
                lock2.unlock();
            }
        }
    } finally {
        lock1.unlock();
    }
}

那个 first != second 的判断是因为 ReentrantLock 是可重入的,转出转入同一个账户时会重复加锁,虽然不会死锁但会加重入计数,unlock 次数对不上就麻烦了。

数据库锁和 JVM 锁交叉的坑

修完上面这个我以为完事了,压测的时候又碰到一次。这次 jstack 里的形态不一样:

"batch-deduct-thread-5" #95 prio=5 os_prio=0 tid=0x00007f9a1c2e3000 nid=0x8f24 runnable
   java.lang.Thread.State: RUNNABLE
    at java.net.SocketInputStream.socketRead0(Native Method)
    at com.mysql.cj.protocol.a.NativeProtocol.readMessage(NativeProtocol.java:555)
    at com.xxx.settle.BatchDeductTask.process(BatchDeductTask.java:112)
    - locked <0x00000006c1a2b3f0> (a com.xxx.settle.AccountLockManager)

这个线程是 RUNNABLE 状态,jstack 检测不出死锁——因为 JVM 层面它只是在等网络 IO,并没有阻塞在 monitor 上。它持着 JVM 锁,在等数据库的行锁

而数据库那边的死锁日志是这样的:

------------------------
LATEST DETECTED DEADLOCK
------------------------
2019-07-08 14:33:21 0x7f2c8c0e9700
*** (1) TRANSACTION:
TRANSACTION 4218934, ACTIVE 12 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1136, 2 row lock(s)
UPDATE account SET balance = balance - 100.00 WHERE id = 1002

*** (2) TRANSACTION:
TRANSACTION 4218935, ACTIVE 11 sec starting index read
UPDATE account SET balance = balance + 100.00 WHERE id = 1001
*** (2) HOLDS THE LOCK(S):  ...
*** WE ROLL BACK TRANSACTION (2)

MySQL 有死锁检测,会主动回滚其中一个事务(innodb_lock_wait_timeout 默认 50 秒,但死锁检测是立即触发的)。所以数据库这边不会永久卡住,回滚之后抛 DeadlockLoserDataAccessException

真正麻烦的是这种组合:线程 A 持 JVM 锁 L1,等数据库行锁 R1;线程 B 持数据库行锁 R1,等 JVM 锁 L1。这种情况下 JVM 检测不到死锁(B 在 monitor 上等,A 在 socket 上等,不构成 monitor 环),数据库也检测不到(A 还没发出 SQL)。两边都干等,直到数据库连接超时或 JVM 锁等待超时。

我们的连接超时配的是 30 秒,所以这个 case 是等 30 秒报错退出,不是永久卡死。但 187 个线程堵着,损失已经造成了。

解决办法是让加锁顺序在 JVM 和数据库两个层面保持一致。我的做法是:

  1. 应用层锁和数据库操作,都按账户 ID 升序执行,SQL 里的 WHERE id IN (...) 也保证顺序。
  2. 加超时。应用层锁用 tryLock(3, TimeUnit.SECONDS) 替代 lock(),拿不到就快速失败,避免无限堆积:
public boolean transferWithTimeout(long id1, long id2, TransferCallback callback) {
    long first = Math.min(id1, id2);
    long second = Math.max(id1, id2);
    ReentrantLock lock1 = lockManager.getLock(first);
    ReentrantLock lock2 = lockManager.getLock(second);

    try {
        if (!lock1.tryLock(3, TimeUnit.SECONDS)) {
            log.warn("lock timeout, accountId={}", first);
            return false;
        }
        try {
            if (first != second && !lock2.tryLock(3, TimeUnit.SECONDS)) {
                log.warn("lock timeout, accountId={}", second);
                return false;
            }
            try {
                callback.doTransfer();
                return true;
            } finally {
                if (first != second) {
                    lock2.unlock();
                }
            }
        } finally {
            lock1.unlock();
        }
    } catch (InterruptedException e) {
        Thread.currentThread().interrupt();
        return false;
    }
}

改完之后我写了个压测脚本,20 个线程随机做 5000 次双向转账(A→B 和 B→A 各一半),跑三轮:

版本完成笔数死锁次数lock 超时失败平均耗时
修复前(随机顺序)2,841 / 50007 次 JVM 死锁0
仅排序5000 / 50000018 ms
排序 + tryLock4,967 / 5000033 次19 ms

第三行那 33 次超时失败是 tryLock 主动放弃的,业务上重试即可,总比整池线程堵死强。生产上我把超时设成了 3 秒,实际观察下来失败率 0.02%,重试一次就成功。

再加一道保险:让程序自己发现死锁

修完之后我还是不放心。死锁这种问题,靠人定期 jstack 是不靠谱的,得让程序自己盯着。ThreadMXBean 提供了现成的 API:

@Component
public class DeadlockDetector {

    private static final Logger log = LoggerFactory.getLogger(DeadlockDetector.class);
    private final ThreadMXBean threadMxBean = ManagementFactory.getThreadMXBean();
    private final ScheduledExecutorService scheduler =
            Executors.newSingleThreadScheduledExecutor(
                    new ThreadFactoryBuilder().setNameFormat("deadlock-detect-%d").build());

    @PostConstruct
    public void start() {
        // 每 30 秒检测一次
        scheduler.scheduleAtFixedRate(this::detect, 30, 30, TimeUnit.SECONDS);
    }

    private void detect() {
        long[] deadlocked = threadMxBean.findDeadlockedThreads();
        //   ↑ 这个方法能检测"可能造成死锁的线程循环等待",
        //     比 findMonitorDeadlockedThreads 更全面(后者只管 synchronized)
        if (deadlocked == null || deadlocked.length == 0) {
            return;
        }

        log.error("DEADLOCK DETECTED, thread count={}", deadlocked.length);
        ThreadInfo[] infos = threadMxBean.getThreadInfo(deadlocked, true, true);
        StringBuilder sb = new StringBuilder();
        for (ThreadInfo info : infos) {
            sb.append("\n--- ").append(info.getThreadName())
              .append(" (id=").append(info.getThreadId())
              .append(", state=").append(info.getThreadState()).append(")")
              .append("\n    waiting on: ").append(info.getLockName())
              .append("\n    owned by  : ").append(info.getLockOwnerName());
            for (StackTraceElement e : info.getStackTrace()) {
                sb.append("\n        at ").append(e);
            }
        }
        log.error(sb.toString());

        // 同时把完整的 jstack 输出存一份到文件,方便事后分析
        dumpAllThreads();
    }
}

这个检测器上线之后,我们在预发环境又抓到一次死锁,是另一个同事新写的优惠券核销逻辑,锁顺序同样没统一。这次在上线前就发现了。

有个坑要注意:findDeadlockedThreads() 在 JDK 8 上,如果线程是在等待 AbstractOwnableSynchronizer(也就是 ReentrantLock 这类)造成的循环等待,它检测出来;但如果环里有线程在等 socket IO(就像上面那个数据库锁交叉的 case),它检测不出来。所以它不是万能的,只是多一层防护。

另外说一下 BLOCKEDWAITING 在 jstack 里的区别,我刚开始老搞混:

  • BLOCKED (on object monitor):线程在进入 synchronized 块时拿不到锁,被动阻塞。它的 waiting to lock <0x...> 指向它想要的锁。
  • WAITING (parking):线程主动调用了 LockSupport.park()ReentrantLock.lock()Object.wait() 最终都走这里)。它可以被 unpark 唤醒。
  • TIMED_WAITING (parking):带超时的 park,比如 tryLock(3, SECONDS)Thread.sleep()

所以判断死锁要看 BLOCKEDWAITING 里那些带 waiting to lock 的线程,它们构成环才是死锁。纯 WAITING (parking) 且没有 waiting to lock 的,多半是线程池里的空闲线程,正常。

排查死锁的固定动作

总结下我现在遇到"线程 BLOCKED / 接口全挂"时的处理顺序:

  1. jstack -l <pid> > /tmp/stack.txt,先看文件末尾有没有 Found one Java-level deadlock。有就直接看是哪两个 monitor。
  2. 没有的话,grep -c 'BLOCKED' /tmp/stack.txt 数一下阻塞线程数,再 grep -A 3 'BLOCKED' | grep 'waiting to lock' 看它们都在等哪个对象地址。如果大量线程等同一个地址,通常是某个长事务或者外部调用把锁持有者卡住了,不是死锁。
  3. 隔 5 秒再抓一份,对比两次的 nid 状态。真死锁的线程状态不会变化,慢查询导致的阻塞会看到进展。
  4. 顺手看一眼数据库:SHOW ENGINE INNODB STATUS\GLATEST DETECTED DEADLOCK 段,以及 SELECT * FROM information_schema.INNODB_LOCK_WAITS

最后一步很重要。这次的第二个 case 就是纯 JVM 层面看不出来的,必须两边对着看。跨资源的死锁,单边工具都无能为力。

留个问题

关于《一次线上死锁排查:jstack 定位与修复》里这个坑,你当时是怎么处理的?欢迎在评论区聊聊你踩过的类似情况。

参考