《Java 并发编程·线程与内存模型》附录 B 并发诊断命令与 JFR 事件

这份附录解决什么

前 15 章讲的是规则，这份附录讲的是怎么在运行中的进程里看见规则失效。内容分三块：jcmd 子命令怎么用、线程转储怎么读、JFR 里哪几个事件对应并发问题。

所有输出都来自本机 Temurin 25.0.5+8，演示程序是一个构造了 BLOCKED、WAITING (parking)、TIMED_WAITING 三种状态的十行类。命令可以照抄，数字随机器变化。

jcmd：一个入口

jstack、jmap、jinfo 的功能在 JDK 25 里都能通过 jcmd 调用。jcmd 不 fork 新进程去 attach，而是在目标 JVM 里执行，开销更小，也不受 -Xmx 影响。

先列进程：

export JAVA_HOME=~/.jdks/jdk-25.0.5+8/Contents/Home
$JAVA_HOME/bin/jcmd -l

本机输出（截取，去掉无关进程）：

5793 DiagDemo
49666 libraryd-app/target/libraryd-app-1.0.0-SNAPSHOT.jar
60252 libraryd-app/target/libraryd-app-1.0.0-SNAPSHOT.jar

第一列是 pid，第二列是主类或 jar。同一个 jar 出现多次说明有多个实例，别抓错进程——抓错时看到的线程数、GC 次数都对不上，容易得出错误结论。

jcmd 的命令分类用 help 看：

$JAVA_HOME/bin/jcmd <pid> help

概况类

本机 VM.flags 的截取（默认参数，未加任何 -Xmx）：

-XX:CICompilerCount=4 -XX:ConcGCThreads=2 -XX:G1HeapRegionSize=4194304
-XX:InitialHeapSize=536870912 -XX:MaxHeapSize=8589934592
-XX:SoftMaxHeapSize=8589934592 -XX:+UseCompressedOops -XX:+UseG1GC
-XX:-UseNUMA -XX:-UseNUMAInterleaving

InitialHeapSize=536870912 是 512 MB，MaxHeapSize=8589934592 是 8 GB，约为物理内存的 1/4。这个默认值对大堆应用经常偏大，容器里更要注意 MaxRAMPercentage。

线程类

抓转储前先连续抓 3 次、每次间隔 5 秒。单次转储只能说明「那一刻」，CPU 飙高的线程可能在两次抓取之间换了人。三次里都在 RUNNABLE 反复出现的栈才是嫌疑。

本机 Thread.print 的关键片段：

"main" #3 [9987] prio=5 os_prio=31 cpu=36.65ms elapsed=4.31s ...
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleepNanos0(java.base@25.0.5/Native Method)

"gate-holder" #25 [27395] ... cpu=0.19ms elapsed=4.26s ...
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleepNanos0(java.base@25.0.5/Native Method)

"gate-waiter" #26 [33027] ... waiting for monitor entry  [0x000000016d7e2000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at DiagDemo.lambda$main$1(DiagDemo.java:18)
	- waiting to lock <0x0000000b6e419298> (a java.lang.Object)

"parked-worker" #27 [43011] ... waiting on condition  [0x000000016d9ee000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@25.0.5/Native Method)
	at java.util.concurrent.locks.LockSupport.park(java.base@25.0.5/LockSupport.java:369)

四行标题里能读出五件事：

• 线程名和 #n（Thread.threadId()）、nid（操作系统线程号，top -H 里对得上）。
• cpu=36.65ms 是该线程累计 CPU 时间，不是当前占用率。要算占用率得抓两次取差值。
• elapsed=4.31s 是线程存活时长，与 cpu 一对比就知道它是不是在空转。
• waiting for monitor entry 与 waiting to lock <地址> 是 BLOCKED 的信号，-l 才会给出 - locked <同一个地址> 的持有者。
• WAITING (parking) 说明线程卡在 LockSupport.park，ReentrantLock、Semaphore、阻塞队列的 take() 都长这样。

BLOCKED 和 WAITING (parking) 的区别是排查方向的分水岭：前者是等监视器，看 waiting to lock 的地址找出持有者；后者是等信号，要找谁本该 unpark 却没做。把两者混为一谈，会去翻根本不相关的 synchronized 代码。

堆与 GC

本机 GC.heap_info（一个刚启动、只有 21 个线程的进程）：

garbage-first heap   total reserved 8388608K, committed 528384K, used 6229K
region size 4096K, 2 young (8192K), 0 survivors (0K)

reserved 是预留地址空间，committed 才是真正占用的物理内存，used 是存活对象。看「内存涨没涨」要看 committed，看 reserved 会得出吓人的错误结论。

JFR 控制

settings=profile 才包含 jdk.VirtualThreadPinned、jdk.JavaMonitorEnter 这类低开销事件；默认的 default 配置采集的事件少得多。录制的开销通常在 1% 以内，但 settings=profile 配上很短的 period 会明显增加 GC 压力。

JFR 事件：并发问题看哪几个

jdk.JavaMonitorEnter

用 settings=profile 录制，命令：

$JAVA_HOME/bin/java -XX:StartFlightRecording=filename=rec2.jfr,settings=profile JfrDemo
$JAVA_HOME/bin/jfr summary rec2.jfr | rg 'JavaMonitorEnter|ThreadPark|VirtualThreadPinned'

本机摘要：

 jdk.ThreadPark                              4           129
 jdk.JavaMonitorEnter                        2            44
 jdk.VirtualThreadPinned                     0             0

第一条与业务无关（jdk.jfr.internal.PlatformRecorder 的内部锁），第二条才是演示里制造的争用：

jdk.JavaMonitorEnter {
  startTime = 23:50:55.303 (2026-10-28)
  duration = 201 ms
  monitorClass = java.lang.Object (classLoader = bootstrap)
  previousOwner = "main" (javaThreadId = 3)
  address = 0xB0D8CFE20
  eventThread = "mon-contender" (javaThreadId = 29)
  ...
}

duration=201ms 是等待时间，不是临界区执行时间。previousOwner 直接告诉你锁在谁手上——这正是 jstack 需要翻上下文才能拼出来的信息。address 可以和 Thread.print -l 里的 waiting to lock <地址> 对上，两个工具就串起来了。

解读时要注意：JavaMonitorEnter 只记录发生过阻塞的进入。没竞争、或竞争但被自适应自旋化解掉的锁，不会产生事件。所以「没有事件」不等于「没有 synchronized」，只等于「没有线程真的被挂起」。

jdk.ThreadPark

jdk.ThreadPark {
  startTime = 23:50:55.505 (2026-10-28)
  duration = 54.5 ms
  parkedClass = N/A
  timeout = 50.0 ms
  until = N/A
  address = 0x00000000
  eventThread = "main" (javaThreadId = 3)
  stackTrace = [
    jdk.internal.misc.Unsafe.park(boolean, long)
    java.util.concurrent.locks.LockSupport.parkNanos(long) line: 408
    JfrDemo.main(String[]) line: 19
  ]
}

三个字段的区分：

• timeout 非 N/A 表示是限时 park，until 非 N/A 表示是带截止时间的 park。两者都为 N/A 才是真正的无限 park，这类事件最值得警惕，因为无外部信号就永远醒不来。
• parkedClass 是 park 时传入的阻塞对象，ReentrantLock 会把自己的 Sync 传进来。N/A 说明调用的是无参 park()，Thread.print 里也不会显示 parking to wait for 行。
• duration 是这次 park 持续了多久，不是累计。

ThreadPark 的 stackTrace 能直接指到业务方法。看到 ArrayBlockingQueue.take 卡住，问题在生产者；看到 CompletableFuture.join 卡住，问题在依赖未完成；看到 LockSupport.parkNanos(50_000_000L) 且 duration 与 timeout 接近，说明是正常超时而不是信号丢失。

jdk.VirtualThreadPinned

JEP 491 之后 synchronized 不再 pin 虚拟线程，这一条是 JDK 24→25 最容易写过时的结论。本机两种 LockingMode 的对照：

LockingMode=1 下的事件详情：

jdk.VirtualThreadPinned {
  startTime = 23:50:56.784 (2026-10-28)
  duration = 60.1 ms
  blockingOperation = "LockSupport.park"
  pinnedReason = "Freeze or preempt failed (4)"
  carrierThread = "ForkJoinPool-1-worker-1" (javaThreadId = 32)
  eventThread = "vt-pin" (javaThreadId = 31, virtual)
  stackTrace = [
    java.lang.VirtualThread.parkOnCarrierThread(boolean, long) line: 833
    java.lang.VirtualThread.parkNanos(long) line: 801
    java.lang.VirtualThread.sleepNanos(long) line: 983
    java.lang.Thread.sleepNanos(long) line: 507
    java.lang.Thread.sleep(long) line: 540
  ]
}

这段输出说明三件事：

• 默认配置下，虚拟线程在 synchronized 块里 Thread.sleep 完全不产生 pinning 事件。网上「虚拟线程里不要用 synchronized」的规则在 JDK 25 已经不成立。
• 事件里的 blockingOperation 是 LockSupport.park 而不是 synchronized，pinnedReason 是 Freeze or preempt failed——这是强制回退到旧锁实现（LockingMode=1）时的行为，不是业务代码的问题。
• carrierThread 指明了被占住的是哪个载体线程。真实 pinning（JNI 调用、类初始化）也会给出线程名，可以和 ForkJoinPool-1-worker-n 的活跃度对照。

虚拟机线程数达到十万级时，一个 pinning 只损失一个载体线程，影响有限；真正的问题是 pinning 期间载体线程无法调度其它虚拟线程，若这类调用频繁且耗时长，吞吐会退化到「载体线程数 × 串行时长」。

一个完整的排查流程

以「接口 RT 从 20ms 涨到 2s」为例，命令顺序如下：

1. jcmd -l 找对 pid，jcmd <pid> VM.flags 确认参数没被改。
2. 连续三次 jcmd <pid> Thread.print > /tmp/dump{1,2,3}.txt，间隔 5 秒。
3. 在三次转储里同时出现的 RUNNABLE 栈，按业务包名过滤。
4. jcmd <pid> Thread.print -l 找 BLOCKED 线程的 waiting to lock 地址，反查 - locked 的持有者。
5. 用 jcmd <pid> JFR.start name=diag settings=profile duration=60s filename=/tmp/diag.jfr 录制一分钟。
6. jfr summary /tmp/diag.jfr 看哪个事件数量异常，再 jfr print --events <事件名> /tmp/diag.jfr 看细节。
7. 若怀疑虚拟线程，加看 jdk.VirtualThreadPinned 与 jdk.VirtualThreadStart。

第 6 步的过滤比输出全量有用得多。jfr print 支持按事件、按时间窗口、按阈值过滤：

jfr print --events jdk.JavaMonitorEnter --stack-depth 10 /tmp/diag.jfr
jfr print --events jdk.ThreadPark --events jdk.JavaMonitorWait /tmp/diag.jfr
jfr print --events jdk.VirtualThreadPinned /tmp/diag.jfr

--stack-depth 默认是 5，业务栈经常被截断，排查时调到 10–20 才能看到调用方。

命令速查表

三个容易误读的输出

第一，cpu= 是累计值。 转储里 cpu=36.65ms 配合 elapsed=4.31s，说明这个线程 4 秒里只用了 36 毫秒 CPU，是典型的等 IO 或被阻塞。反过来，cpu 接近 elapsed 才是空转。

第二，reserved 不是内存占用。 G1 会预留一整块地址空间，GC.heap_info 第一行的 total reserved 经常是 MaxHeapSize 的量级。判断内存压力看 committed 与 used，必要时配 -Xlog:gc 看真实回收行为。

第三，JFR 里没有事件不代表没有竞争。 低竞争下自适应自旋能吃掉大部分等待，JavaMonitorEnter 一条都不产生；锁消除、锁粗化也会让源码里的 synchronized 在机器码里消失。JFR 反映的是「运行时真的发生了什么」，不是「源码写了什么」，两者要分开陈述。

与卷三的分工

这份附录给的是命令与读法。完整的压测方案、指标采集、事故复盘模板、以及多个真实故障的定位路径在卷三展开，那里会把这里的命令串成可复用的排查手册。卷二则解释事件背后的结构：AQS 的队列与状态、ConcurrentHashMap 的 bin 锁、Striped64 的分片，知道结构之后，转储里的地址与栈才不只是符号。