Java虚拟线程服务中jstack会遗漏什么
设想一个启用了虚拟线程的 Spring Boot 服务,HikariCP 连接池有 10 个连接,大约有 5,000 个请求正在处理中。延迟持续上升。你抓取了一份线程转储,发现只有 43 个平台线程,其中大多数调度器工作线程都停在 ForkJoinPool.awaitWork,CPU 活动很少。
如果你用的是 jstack,你要找的请求可能根本没有进入文件。在 JDK 21 到 25 上,传统转储不会列出虚拟线程。你可能花很长时间阅读调度器的栈,却始终看不到那些在等待数据库的请求。
本文将一直使用这个连接池场景。数字和转储片段仅作示例。我负责维护 ThreadMine,它对上述格式的支持也需要一些说明;我会在命令之后讲到。
如果你更想先从头到尾看一遍流程,这个两分钟的演示会带你从捕获转储走到共享报告:
请求等待时,载体线程可能处于空闲
jstack 和 jcmd <pid> Thread.print 显示的是平台线程。这也包括载体线程,即运行虚拟线程的调度器工作线程。当虚拟线程卸载(unmount)以等待 I/O 或其他资源时,它的载体线程就可以空闲出来去运行其他任务。
如果大多数请求都在等待,载体线程可能几乎无事可做。低 CPU 和空闲的工作线程,与大量积压完全可能同时存在。
调度器使用 ForkJoinPool,默认并行度基于 JVM 可用的处理器数量。你可以通过 jdk.virtualThreadScheduler.parallelism 修改它,但在我弄清楚请求到底在等什么之前,我会先不动它。增加更多工作线程,不会帮助那些排在同 10 个数据库连接后面的请求。
一个已挂载虚拟线程的载体线程,可能会在传统转储中包含下面这一行:
从 JDK 24 开始,转储还会在载体线程下面打印该虚拟线程自己的栈,前面有一行 Mounted virtual thread #212。无论哪种方式,这对于识别已挂载的线程都很有用。对于成千上万个未挂载的线程,你需要另一种转储。
使用 Thread.dump_to_file
这个命令从 JDK 21 起就已可用:
JVM 会写入该文件,因此 /tmp/dump.txt 是目标进程文件系统中的路径。这在容器里很重要。进程还需要有写入该位置的权限;捕获指南介绍了这些细节。
默认是纯文本。要输出 JSON:
文档中给出的格式名是 plain 和 json。除非传入 -overwrite,否则不会覆盖已有文件。每次捕获都使用新的文件名,这样以后才有东西可以比较。
输出还取决于 JDK 版本。JDK 21 到 24 会给出线程 ID、名称、virtual 标记和栈。JDK 25 增加了状态、时间戳和锁信息。一个简短的 JDK 25 条目可能如下所示:
这就是那个请求,它正在等待获取一个连接。名称为空在虚拟线程中很常见;如果应用需要,可以给它分配一个名称。
就我们的例子而言,假设文件包含 5,004 个虚拟线程,以及 4,962 处 HikariPool.getConnection。无需把转储加载到任何工具中,就可以检查这些计数:
第二条命令统计匹配的行数。打开几个栈检查调用路径,尤其是当该方法在每个线程中出现不止一次时。
此时,我会查看连接持有时间。如果每个请求持有连接 18 毫秒,那么在没有新请求到达的情况下,10 个连接大约需要 9 秒才能清空 5,000 个请求的积压。这让我们对延迟的量级有了一个合理估计。它不会计算 p99,但会告诉我们应该从哪里开始调查。
在调整连接池大小之前,检查慢查询和事务范围。例如,一个连接在无关的 HTTP 调用期间被持有,会减少其后每个请求可用的容量。数据库可能支持更高的并发,也可能已经不堪重负。转储有助于定位队列;连接池和数据库指标有助于解释它。
虚拟线程让等待变得更便宜。数据库仍然必须完成工作。
在下一份转储中,我会比较什么
对于持续数分钟的变慢,大约 30 秒后再做一次捕获。查看大的栈分组,并比较其中的线程 ID。
如果相同的请求仍在相同位置等待,就要调查它们为什么没有进展。如果 ID 已经变化,但分组仍然很大,那么请求可能正在完成,同时新请求又填满了队列。如果只比较总数,这两种情况看起来几乎一样。
我不会过度解读 5,004 个线程变成 5,011 个线程。我更关心连接获取时间是否在上升,以及吞吐量是否已经跟不上新到达的请求。我不止一次被单份转储误导过,而第二份转储的成本总是很低。
状态标签也需要同样处理。在一个执行 I/O 的服务中,WAITING 是预期状态,它本身不能告诉你虚拟线程是否释放了载体线程。RUNNABLE 也不能证明 CPU 已饱和。先从栈和涉及的资源入手,然后检查那些可能解释等待的指标。
当存在多个执行器时,JSON 会更有帮助
对于一大批等待 HikariCP 的请求,文本文件足以开始分析。当你需要区分不同执行器或结构化并发作用域创建的工作时,JSON 就会变得有用。它会把线程分组到容器中。
在 JDK 25 上,已挂载虚拟线程的条目还可以包含其载体线程的 ID。下面是一个缩减后的容器,其中只有一个线程:
对完整的 JDK 25 JSON 文件运行以下命令,以统计带载体线程的虚拟线程条目,并列出容器大小:
转储是在线程继续运行时收集的。因此,这个载体线程计数并不是在某一瞬间有多少载体线程处于忙碌状态的测量。我会首先使用容器细分来找出线程正在哪里累积。
请把 JDK 版本和文件一起保留。这里使用的一些字段在旧版本中不可用。还要检查 -Djdk.trackAllThreads=false,它可能会让一些虚拟线程不出现在转储中。
固定(pinning)取决于 JDK 版本
一个请求在等待连接,和一个虚拟线程阻塞其载体线程,需要不同的排查方向。对于第二种情况,要查找 VirtualThread.parkOnCarrierThread:这是虚拟线程在保留载体线程的同时停驻的路径。
在 JDK 21 到 23 上,当 HTTP 调用阻塞时,这段代码可能会走那条路径:
栈的相关部分可能如下所示:
在 JDK 24 和 JEP 491 中,持有监视器不再导致这种固定。其他情况下仍可能涉及原生帧和类初始化。在建议修改 synchronized 代码之前,请检查运行时版本。
对于时有时无的固定,我会使用 JFR。jdk.VirtualThreadPinned 事件自 JDK 21 起就默认启用,阈值为 20 毫秒。一次记录会给出频率和持续时间,而这两点很容易被几份转储漏掉。旧的 jdk.tracePinnedThreads 选项已在 JDK 24 中移除。
发现 parkOnCarrierThread 是那条特定停驻路径的有用证据。它没有出现,并不能排除所有形式的固定。关于版本差异的更多内容,请参阅 pinning 参考。## 关于 ThreadMine 的说明
ThreadMine 可以读取 Thread.dump_to_file 写出的文本文件,并支持它迄今为止出现过的两种格式:JDK 21 至 24 的格式(头部不含状态信息,栈帧中也没有 at),以及 JDK 25 的格式(两者都具备)。虚拟线程会按虚拟线程呈现,空名称保持为空,而停留在 parkOnCarrierThread 中的线程会被标记为已固定(pinned)。坦白说,这项能力还非常新:直到本周之前,解析器仍会静默丢弃每一行 #22 "" virtual,我是在用 JDK 21 到 JDK 25 的真实转储核对本文时才发现的。目前仍不接受 JSON 形式,所以请粘贴文本内容;至于按容器统计数量,仍是 jq 能做而分析器做不到的一件事。
如果要给团队的事故响应手册(runbook)提一条修改建议,那很直接:当服务使用虚拟线程时,除了传统的线程转储,还要抓取 Thread.dump_to_file。你需要在任何人开始根据空闲的载体线程(carrier)下结论之前,先拿到请求栈。
Felipe Maschio 是 ThreadMine 的创始人,ThreadMine 是一款免费的 JVM 线程转储分析器。
参考资料
Felipe Maschio
来自巴西库里蒂巴的软件工程师,专注于 JVM 性能与线程转储分析。他是 JVM 线程转储分析器 ThreadMine 的创始人。在 Project Loom、虚拟线程固定(pinning),以及它悄无声息地限制吞吐量的种种方式上拥有丰富经验……