《Java 并发编程·性能诊断与事故》3.1 JFR 的 Monitor 事件

从 4 线程抢同一把监视器锁的实跑出发,说明 jdk.JavaMonitorEnter、jdk.JavaMonitorWait 与 jdk.ThreadPark 各自记录什么,profile.jfc 的 10 ms 默认阈值如何过滤掉短竞争,并给出 jfr summary、jfr view 与 jfr print 的真实输出,最后用 LongAdder 改造验证竞争消失。

承接的问题

2.3 把微基准和系统压测的边界划清了:JMH 能回答「一次操作在本机要多少纳秒」,回答不了「线上这 300 ms 到底花在哪个锁上」。进入第 3 章,工具从受控实验换成运行态观测,第一个要解决的就是锁竞争。

典型症状是这样:接口 RT 从 40 ms 涨到 300 ms,CPU 利用率只有 35%,线程池没有满,日志里也没有异常。抓一份线程转储,能看到一片 BLOCKED (on object monitor),但不知道谁持有锁、持有了多久。打开 JFR,jfr view contention-by-class 可能只剩很少几条,甚至只有 JFR 自己的 PlatformRecorder,看起来「没有锁竞争」。

这三个现象指向同一组问题:

  • jdk.JavaMonitorEnter 到底在什么时候提交,duration 量的是等待还是持有;
  • settings=profile 的默认阈值是多少,为什么它会把大量短竞争直接丢掉;
  • jfr summary、jfr view、jfr print 各看什么,怎么从事件回到代码行。

本节的实验都跑在同一台机器上:

Apple M1 Pro,10 核,32 GB,macOS 26.3 (25D125)
Temurin 25.0.5+8

写作时 uptime 的 load average 是 108.37 119.89 117.88。所有计时数字都是单次运行、随调度波动、不作基准;本节只比较方向,不比较绝对快慢。

三个事件各记什么

JFR 的锁相关事件不止一个。名字写错,--events 过滤器会静默返回空,所以先把分工钉死。

事件JFR 标签提交时机关键字段本卷出现
jdk.JavaMonitorEnterJava Monitor Blocked线程等待进入 synchronized 监视器,最终进入后提交monitorClass、previousOwner、address、duration3.1、4.1、11.1
jdk.JavaMonitorWaitJava Monitor WaitObject.wait 返回、超时或被中断后提交monitorClass、notifier、timeout、timedOut、address3.1、4.2
jdk.ThreadParkJava Thread ParkLockSupport.park 返回后提交parkedClass、timeout、until、address3.1、5.3、10.3

三个事件都是持续时间事件:startTime 回填为等待开始的时刻,duration 是等待时长,不是持有锁的时长。想看「这把锁被持有多久」,JFR 的这三个事件回答不了,要结合 3.2 的采样和 3.3 的转储。

previousOwner 是竞争开始时的持有者,不等于整段等待里唯一的持有者。监视器可能在等待期间被交接给别的线程;这个字段只适合回答「我一开始在等谁」。

monitorClass 是被锁对象的运行时类,不是变量声明类型。锁 new Object() 时它是 java.lang.Object;锁一个 Book 实例时它是 Book。address 是监视器地址,同一次录制里相同地址代表同一个对象;跨录制、跨进程不能拿地址做比较,GC 之后地址也可能被复用。

最容易踩的坑是锁的实现方式。ReentrantLock 的竞争不会产生 jdk.JavaMonitorEnter,它走 LockSupport.park,对应 jdk.ThreadPark。本机另写一个把临界区改成 ReentrantLock 的靶子(同一进程里还保留 wait/notify 线程)后,同一份录制里 jdk.JavaMonitorEnter 只剩 2 条,其中 1 条是 JFR 自己的 PlatformRecorder,另 1 条来自通知线程进入监视器;jdk.ThreadPark 涨到 8366 条。看到 Monitor 事件为空,先确认代码里等的是监视器还是 AQS。

阈值:10 ms 的默认值会过滤掉短竞争

先把一个容易写错的命令说清楚:JDK 25 的 jfr 命令行没有 start 子命令。它只有 print、view、summary、configure、metadata、scrub、assemble、disassemble。启动录制只有两条路:JVM 启动参数,或 jcmd 的 JFR.start。

# 方式一:启动时挂参数
java -XX:StartFlightRecording=filename=/tmp/lock.jfr,settings=profile,dumponexit=true \
  -cp classes MicroLockProbe

# 方式二:对运行中的进程
jcmd <pid> JFR.start name=lock settings=profile duration=5s filename=/tmp/lock.jfr
jcmd <pid> JFR.dump name=lock filename=/tmp/lock.jfr
jcmd <pid> JFR.stop name=lock

settings=profile 不是「全量录制」。本机 $JAVA_HOME/lib/jfr/profile.jfc 里,jdk.JavaMonitorEnter 的阈值是 10 ms;default.jfc 里是 20 ms。有些资料笼统写 20 ms,那是 default.jfc 的值,profile 配置在本机是 10 ms。以你机器上的 jfc 为准:

rg -A3 '<event name="jdk.JavaMonitorEnter"' "$JAVA_HOME/lib/jfr/profile.jfc"
    <event name="jdk.JavaMonitorEnter">
      <setting name="enabled">true</setting>
      <setting name="stackTrace">true</setting>
      <setting name="threshold" control="locking-threshold">10 ms</setting>

阈值是按事件时长过滤,不是按固定速率采样:每次等待只要不短于阈值就记录,短于阈值就丢掉。它和 async-profiler 的采样是两种口径,3.2 会对照。profile.jfc 里这些锁事件的 threshold 都挂在 locking-threshold 控制项下;但命令行覆盖是按事件写的,只改 JavaMonitorEnter 不会顺带放开 ThreadPark,要逐个事件设置。

覆盖阈值最直接的方式是启动参数里追加事件设置:

java -XX:StartFlightRecording=filename=/tmp/lock-zero.jfr,settings=profile,\
jdk.JavaMonitorEnter#threshold=0ms,jdk.ThreadPark#threshold=0ms,dumponexit=true \
  -cp classes MicroLockProbe

在线进程不能改启动参数,做法是先复制一份配置再启动录制:

jfr configure --input "$JAVA_HOME/lib/jfr/profile.jfc" \
  --output /tmp/zero-lock.jfc \
  jdk.JavaMonitorEnter#threshold=0ms jdk.ThreadPark#threshold=0ms

jcmd <pid> JFR.start name=lock settings=/tmp/zero-lock.jfc duration=30s \
  filename=/tmp/lock-live.jfr

这两条命令在本机对 DumpTarget 进程跑通过,jfr configure 会输出 Configuration written successfully to: /private/tmp/.../zero-lock.jfc,JFR.start 会返回 Started recording 1。阈值取 0 的代价是事件量随竞争次数线性上涨,生产上一般从 1 ms 到 10 ms 起步,只在短窗口内用 0。

实跑:4 个线程抢同一把监视器锁

靶子只做一件事:4 个平台线程反复进入同一个 synchronized 块,块里做一次自增。临界区越短,默认阈值越容易把它过滤掉。

public final class MicroLockProbe {
    private static final Object LOCK = new Object();
    private static long counter;
    private static volatile boolean running = true;

    public static void main(String[] args) throws Exception {
        Thread[] threads = new Thread[4];
        for (int i = 0; i < threads.length; i++) {
            int id = i;
            threads[i] = Thread.ofPlatform().name("micro-" + id).start(() -> {
                while (running) {
                    synchronized (LOCK) {
                        counter++;
                    }
                }
            });
        }
        Thread.sleep(2_000);
        running = false;
        for (Thread t : threads) {
            t.join();
        }
        System.out.println("counter=" + counter);
    }
}

编译并按两种阈值各录一次:

javac --release 25 -d classes MicroLockProbe.java

java -XX:StartFlightRecording=filename=out/micro-default.jfr,settings=profile,dumponexit=true \
  -cp classes MicroLockProbe

java -XX:StartFlightRecording=filename=out/micro-zero-3s.jfr,settings=profile,\
jdk.JavaMonitorEnter#threshold=0ms,dumponexit=true \
  -cp classes MicroLockProbe

两次运行的自增结果分别是 counter=9180874 和 counter=11227070。两份录制文件的 Duration 都是 2 s,但机器负载不同,所以只比较阈值的过滤方向,不把事件数换算成速率。jfr view 的对照:

录制java.lang.Object 事件数AvgP90Max
settings=profile(10 ms)1011.1 ms14.8 ms15.0 ms
jdk.JavaMonitorEnter#threshold=0ms7,8950.504 ms1.62 ms14.0 ms

默认配置下只剩 10 条,因为只有等待不短于 10 ms 的竞争才会被记录;把阈值降到 0,同样的代码在同样的 2 秒窗口里记下 7,895 条,平均等待只有 0.504 ms。默认那条 Avg 11.1 ms 不是「竞争更严重」,而是低于 10 ms 的样本被删掉了,剩下的自然都偏大。

jfr summary 的原始行如下(threshold=0ms 那次):

 jdk.JavaMonitorEnter                     7897        161689

jfr view 先看按类聚合,命令和输出如下:

jfr view --width 100 contention-by-class out/micro-zero-3s.jfr
jfr view --width 100 contention-by-site out/micro-zero-3s.jfr
java.lang.Object                                                     7,895 0.504 ms 1.62 ms 14.0 ms
jdk.jfr.internal.PlatformRecorder                                        2  1.55 ms  3.07 ms  3.07 ms

按站点聚合时,7,895 条中有 7,895 条落在 MicroLockProbe.lambda$main$0() 这一行,另外 2 条来自 JFR 自身(PlatformRecorder.periodicTask() 和 PlatformRecording.isToDisk())。jfr print 给出单条事件的完整字段,默认阈值下的一条 duration 正好落在 10.0 ms:

jdk.JavaMonitorEnter {
  startTime = 02:06:17.216 (2026-10-29)
  duration = 10.0 ms
  monitorClass = java.lang.Object (classLoader = bootstrap)
  previousOwner = "micro-1" (javaThreadId = 30)
  address = 0xA208040E0
  eventThread = "micro-0" (javaThreadId = 29)
  stackTrace = [
    MicroLockProbe.lambda$main$0() line: 12
    java.lang.Thread.run() line: 1474
  ]
}

阈值 0 下的短事件则是 duration = 0.0465 ms、previousOwner = "micro-3"、eventThread = "micro-1",两个线程 ID 不同,说明这是一次真实的交接,不是自旋。从一条事件能读出四件事:等待时间、竞争开始时的持有者、被锁对象、等待者自己的栈。eventThread 是等待者,previousOwner 是它开始等的时候的持有者。

jfr print 默认只打印 5 层栈,业务栈深时加 --stack-depth:

jfr print --events jdk.JavaMonitorEnter --stack-depth 12 out/micro-zero-3s.jfr

Object.wait 与 ThreadPark 的记录方式

MicroLockProbe 只覆盖了监视器进入。再看一个同时包含 Object.wait 和 ReentrantLock 的靶子:

import java.util.concurrent.locks.LockSupport;
import java.util.concurrent.locks.ReentrantLock;

public final class WaitParkProbe {
    private static final Object WAIT_MONITOR = new Object();
    private static final ReentrantLock LOCK = new ReentrantLock();
    private static volatile boolean running = true;

    public static void main(String[] args) throws Exception {
        Thread waiter = Thread.ofPlatform().name("loan-wait").start(() -> {
            while (running) {
                synchronized (WAIT_MONITOR) {
                    try {
                        WAIT_MONITOR.wait(20);
                    } catch (InterruptedException e) {
                        return;
                    }
                }
                LockSupport.parkNanos(2_000_000L);
            }
        });
        Thread notifier = Thread.ofPlatform().name("loan-notify").start(() -> {
            while (running) {
                synchronized (WAIT_MONITOR) {
                    WAIT_MONITOR.notifyAll();
                }
                try {
                    Thread.sleep(20);
                } catch (InterruptedException e) {
                    return;
                }
            }
        });
        Thread holder = lockLoop("loan-lock-holder");
        Thread contender = lockLoop("loan-lock-waiter");

        Thread.sleep(3_000);
        running = false;
        waiter.interrupt();
        notifier.interrupt();
        waiter.join();
        notifier.join();
        holder.join();
        contender.join();
    }

    private static Thread lockLoop(String name) {
        return Thread.ofPlatform().name(name).start(() -> {
            while (running) {
                LOCK.lock();
                try {
                    Thread.sleep(0, 500_000);
                } catch (InterruptedException e) {
                    return;
                } finally {
                    LOCK.unlock();
                }
            }
        });
    }
}

录制时把三个事件的阈值一起放开:

javac --release 25 -d classes WaitParkProbe.java
java -XX:StartFlightRecording=filename=out/waitpark.jfr,settings=profile,\
jdk.JavaMonitorEnter#threshold=0ms,jdk.JavaMonitorWait#threshold=0ms,\
jdk.ThreadPark#threshold=0ms,dumponexit=true \
  -cp classes WaitParkProbe

jfr summary 的三行:

 jdk.ThreadPark                           3899        142948
 jdk.JavaMonitorWait                       133          3176
 jdk.JavaMonitorEnter                        3            61

jdk.JavaMonitorWait 的一条:

jdk.JavaMonitorWait {
  startTime = 02:09:37.428 (2026-10-29)
  duration = 0.102 ms
  monitorClass = java.lang.Object (classLoader = bootstrap)
  notifier = "loan-notify" (javaThreadId = 30)
  timeout = 20.0 ms
  timedOut = false
  address = 0xC55155180
  eventThread = "loan-wait" (javaThreadId = 29)
  stackTrace = [
    java.lang.Object.wait0(long)
    java.lang.Object.wait(long) line: 389
    WaitParkProbe.lambda$main$0() line: 14
    java.lang.Thread.run() line: 1474
  ]
}

notifier 是调用 notifyAll 的线程,timeout 是 wait(20) 传入的上限,timedOut=false 说明这次是被通知唤醒、不是超时。并不是每条都有 notifier:超时或被中断时它可能是 N/A,所以不能拿 notifier 是否存在判断有没有竞争。

jdk.ThreadPark 的一条(摘录,省略 until 与中间 AQS 栈帧):

jdk.ThreadPark {
  startTime = 02:09:37.429 (2026-10-29)
  duration = 0.639 ms
  parkedClass = java.util.concurrent.locks.ReentrantLock$NonfairSync (classLoader = bootstrap)
  timeout = N/A
  address = 0x61EECB9A0
  eventThread = "loan-lock-waiter" (javaThreadId = 32)
  stackTrace = [
    jdk.internal.misc.Unsafe.park(boolean, long)
    java.util.concurrent.locks.LockSupport.park(Object) line: 223
    java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer$Node, int, boolean, boolean, boolean, long) line: 790
    java.util.concurrent.locks.ReentrantLock$Sync.lock() line: 154
  ]
}

parkedClass 是 ReentrantLock$NonfairSync,timeout=N/A 表示无超时 park。栈里的 acquire(Node, int, boolean, boolean, boolean, long) 是 JDK 25 的新 AQS 主路径,卷二已经讲过;看到这串签名,就能确认等的是 AQS 而不是监视器。ThreadPark 的 eventThread 同样是等待者,持有者不在这条栈里,要找持有者得回到 3.3 的转储或看 Locked ownable synchronizers。

在 libraryd-conc 里落地

conc-ops 不把 JFR 当一次性手工工具,而是固定成一段可复用的采集脚本。下面的脚本对运行中的进程开 30 秒自定义阈值录制,结束后直接出两张聚合表:

#!/bin/sh
set -eu
PID=$1
OUT=${2:-/tmp/conc-lock}
DURATION=${3:-30}
mkdir -p "$OUT"

jfr configure --input "$JAVA_HOME/lib/jfr/profile.jfc" --output "$OUT/lock.jfc" \
  jdk.JavaMonitorEnter#threshold=0ms jdk.JavaMonitorWait#threshold=0ms jdk.ThreadPark#threshold=0ms

jcmd "$PID" JFR.start name=conc-lock settings="$OUT/lock.jfc" \
  duration="${DURATION}s" filename="$OUT/lock.jfr"
sleep $((DURATION + 2))
jfr summary "$OUT/lock.jfr" | grep -E 'JavaMonitor|ThreadPark'
jfr view --width 140 contention-by-class "$OUT/lock.jfr"
jfr view --width 140 contention-by-site "$OUT/lock.jfr"

脚本的关键不是命令本身,而是三件事:阈值写进独立的 jfc,不污染 JDK 自带配置;录制窗口固定,避免事件量失控;录完立刻按类和站点聚合,先看热点再看单条事件。生产上把 0ms 改成 1ms 或 5ms,并把 duration 控制在 30 秒以内。要在应用内埋录制,用 jdk.jfr.Recording 加 enable("jdk.JavaMonitorEnter").withThreshold(Duration.ZERO) 即可,API 与命令行是同一套事件设置,不再单独展开。

常见错误与边界

  • 把 jfr start 当命令。 JDK 25 没有这个子命令,正确入口是启动参数或 jcmd JFR.start。
  • 只改 JavaMonitorEnter 的阈值。 ReentrantLock 竞争走 ThreadPark,不放开它,看到的仍然是「没有锁」。
  • 把 duration 当成持锁时间。 它是等待时间;持锁时间要靠采样或业务埋点。
  • 把 previousOwner 当成唯一持有者。 监视器可能在等待期间交接,这个字段只表示竞争开始时的持有者。
  • 拿地址跨录制比较。 同一次录制里相同地址是同一个对象;跨进程、跨 GC 之后没有可比性。
  • 在生产上长期开 threshold=0ms。 事件量随竞争次数上涨,录制文件、磁盘 I/O 和 JFR 自身开销都会跟着涨;短窗口抓现场可以,长期常开要用 1–10 ms。
  • 把 JavaMonitorWait 都当竞争。 工作线程等任务队列也会 wait;要看 notifier、timeout、栈和业务语义,不能只看条数。
  • 以为 JFR 覆盖所有锁。 StampedLock、Semaphore、Condition.await 等走的是 park 或其他路径;先确认事件类型,再解释数据。

小结

JFR 的锁诊断有三层:事件层看 JavaMonitorEnter、JavaMonitorWait、ThreadPark 各自记什么;配置层看 profile.jfc 的 10 ms 阈值和 #threshold=0ms 的覆盖方式;聚合层用 jfr view contention-by-class/site 把事件压回代码行,再用 jfr print 看单条的 previousOwner、address、notifier。

本节最重要的两个实测结论:默认 profile 下 2 秒只留下 10 条不短于 10 ms 的竞争,阈值降到 0 后同一份代码记下 7,895 条、平均 0.504 ms;ReentrantLock 的竞争不会出现在 JavaMonitorEnter 里,而是 ThreadPark。把临界区里的 synchronized 自增换成 LongAdder 后,同样的 0 ms 录制里 java.lang.Object 的竞争事件归零,只剩 JFR 自己的 2 条 PlatformRecorder。修复是否有效,用同一套录制参数复跑一次就能验证。

阅读导航:上一节 2.3 从微基准到系统压测 | 下一节 3.2 async-profiler 的锁与分配火焰图

继续阅读

探索更多技术文章

浏览归档,发现更多关于系统设计、工具链和工程实践的内容。

全部文章 返回首页

「books」更多文章

  1. 《Java 消息中间件·事件驱动架构》附录 B 架构决策记录模板
  2. 《Java 消息中间件·事件驱动架构》附录 A 术语表
  3. 《Java 消息中间件·事件驱动架构》15.3 全书验收