一把空锁卡死整个服务：虚拟线程 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 个线程在排队，这就怪了。

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

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

1. 队头的虚拟线程被 unpark 了，但等不到载体线程，一直没能去拿锁
2. 载体线程被 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会顺手编一个说得通的故事补上，并且经常跑偏。这次它给过好几个解释，听着都合理，其实一个都没验证过。

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

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

强大的AI是顺风帆，能让船提速，但航线始终由舵手来定