一把空锁卡死整个服务：JDK 21 虚拟线程 pinning 假死排查实战

锁没人持有，288 个线程却排了 13 小时的队：一次虚拟线程 pinning 假死的排查

JDK 21 的服务，日志不写了，接口全超时，jstack 里还找不到谁持有锁。最后发现问题出在虚拟线程的调度器上，和锁本身关系不大。

现象

测试环境有个服务（JDK 21，8 核机器）晚上突然假死了：

应用日志停在某个时间点，之后 13 小时一行都没写
进程还在，GC 正常，arthas 也能连上
对外的 Dubbo 查询接口全部超时
jstack 里一大堆线程卡在同一把 ReentrantLock 上，但整份 dump 里找不到谁持有这把锁

卡住的线程都在打日志，栈长这样：

at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:322)
at java.util.concurrent.ArrayBlockingQueue.remainingCapacity(ArrayBlockingQueue.java:485)
at ch.qos.logback.core.AsyncAppenderBase.append(AsyncAppenderBase.java:162)
...

线程是卡在 logback AsyncAppender 内部队列的锁上。所有要打日志的线程都在这排队，业务代码跑不下去，整个服务就停了。

先补点背景

后面会用到三个概念，先说一下。

虚拟线程要借载体线程（carrier）才能跑。 虚拟线程不是 OS 线程，它得被调度到载体线程上才能执行。载体线程在一个 ForkJoinPool 里，默认数量等于 CPU 核数，8 核就是 8 条。

ReentrantLock 阻塞会让出载体线程，synchronized 阻塞不会。 虚拟线程在 lock.lock() 上等的时候会 park，载体线程腾出来给别人用。但在 synchronized 上等的时候（JDK 21 的实现），虚拟线程是被钉在载体线程上的，载体线程跟着一起阻塞，调度器没办法。这就是 pinning。

虚拟线程变成 RUNNABLE，不等于它在跑。 锁释放之后，ReentrantLock 会 unpark 队头的线程。对虚拟线程来说，unpark 只是把它重新丢回调度器的队列里，它还得等分到一条载体线程才能真的执行。

结论

问题	答案
卡在哪	logback `AsyncAppender` 队列的 `ReentrantLock`，状态是 `Unlocked`，却有 288 个线程在排队
锁是空的，为什么没人能拿到	队头的虚拟线程被唤醒了，但分不到载体线程，没法执行去拿锁
载体线程为什么分不出来	8 条载体线程都被 pin 住了：有虚拟线程在 `synchronized` 里等这把日志锁，它占着载体线程不放，其他线程也被它堵在 `synchronized` 外面

排查过程

第一步：线程 dump 看不到持锁的线程

最直接的想法是在 dump 里找谁持有这把锁。第一份 jstack 没带 -l，白看了。重新抓了带 -l 的，还是没有。

原因是 jstack 不会列出虚拟线程。换成 jcmd Thread.dump_to_file 倒是能看到虚拟线程，可这次抓到的 json 和 text 两种格式里都没有锁信息。

所以线程 dump 在这个场景下回答不了"谁持有锁"，得换个办法。

第二步：直接问这把锁

arthas 想反射读 exclusiveOwnerThread，被模块封装挡了（java.util.concurrent 没开 --add-opens）。

换个思路。ReentrantLock.toString() 是公开方法，会打印 [Locked by thread xxx] 或者 [Unlocked]。用 vmtool 把全堆的 ReentrantLock 扫一遍，挑出排队最长的：

vmtool --action getInstances --className java.util.concurrent.locks.ReentrantLock --limit 999999 \
  --express "instances.{? #this.getQueueLength() > 10}.{#this.toString() + ' qlen=' + #this.getQueueLength()}"

结果：

java.util.concurrent.locks.ReentrantLock@7ced673d[Unlocked] qlen=288

全堆 27221 个 ReentrantLock，排队超过 10 个的只有这一把，而且是 Unlocked。没人占着锁，却有 288 个线程在排队，这就怪了。

第三步：怀疑载体线程不够用

锁是空的，排队的里面又有大量虚拟线程，我想到两种可能：

队头的虚拟线程被 unpark 了，但等不到载体线程，一直没能去拿锁
载体线程被 synchronized 里的线程钉住了

先看虚拟线程的状态。同一批任务的 614 个虚拟线程：

状态	数量	占比
RUNNABLE	439	73%
WAITING	156	25%
BLOCKED	7	1%

439 个 RUNNABLE 却没一个在推进，说明它们是被唤醒了，在等载体线程。

再看那 7 个 BLOCKED，全卡在同一个地方：

java.util.concurrent.ConcurrentHashMap.compute
  ← Caffeine BoundedLocalCache.computeIfAbsent
  ← LocalLoadingCache.get
  ← UserService.get(UserService.java:229)
  ← ... 业务批处理逻辑 ...
  ← VirtualThread.run

ConcurrentHashMap.compute 内部是 synchronized。这 7 个线程在等别人手里的监视器，那持有监视器的是谁？

翻线程栈能看到，持有者也是一个虚拟线程，它正在 compute 的加载逻辑里打日志，等的就是那把日志锁。它在 synchronized 里等锁，所以载体线程被钉死了，那 7 个等监视器的线程也一样，各占一条载体线程动不了。

最后直接读虚拟线程默认调度器 VirtualThread.DEFAULT_SCHEDULER 的状态：

ForkJoinPool[Running, parallelism = 8, size = 30, active = 8, running = 0, ...]

active = 8、running = 0。8 条载体线程全被占着，真正在跑代码的一条都没有。

串起来看

flowchart TD A[批量任务：一下子产生几百个虚拟线程] --> B[大量虚拟线程打日志，争抢 AsyncAppender 队列锁] A --> C[虚拟线程进入缓存加载的 synchronized] C --> D[持有监视器的线程在里面打日志，等日志锁] D --> E[它被 pin 在载体线程上；等监视器的线程也被 pin 住] E --> F[8 条载体线程被占满，active=8 running=0] B --> G[日志锁释放，AQS unpark 队头的虚拟线程] G --> H[变成 RUNNABLE，但要等载体线程才能执行] F --> H H --> I[没有载体线程，队头拿不到锁，锁空着，队列越排越长] I --> J[平台线程、Dubbo 查询线程也要打日志，全排进这把锁] J --> K[日志冻结，接口超时，持续 13 小时]

这是跨了两层的死锁：

应用层：持有监视器的线程要先拿到日志锁，才能退出 synchronized
调度层：日志锁队头的线程要先有载体线程，才能去拿这把锁，而载体线程正被上面那些线程占着

单看哪一层都没毛病，所以 jstack 看不出死锁，JVM 自己也不会报死锁。

这次的问题是我和ai一起排查的

我觉得，查问题难的找线索，验证假设。假设随时能想出几个，但每个都要花时间去扫堆、查状态、对数字。AI 把验证这一步压得很短，一条命令几分钟就有结果。

但证据不够的时候，ai会顺手编一个说得通的故事补上，并且经常跑偏。这次它给过好几个解释，听着都合理，其实一个都没验证过。

所以我主要做两件事：它下结论时问一句"凭什么"；它没方向时，用我的知识给它方向，载体线程被占满这个假设就是这么来的。

我给方向，它去验证，没证据的结论不算数。