Java——一次锁竞争的完整定位

一个接口的 p50 从 23ms 变成 1.5 秒、QPS 从 2756 掉到 41，而机器几乎不忙。这篇记录把这个现象定位到锁竞争的全过程。
顺序是：先造一个「把 20ms 下游调用写进 synchronized 块」的服务并把症状跑出来，再用 jcmd <pid> Thread.print 找到 63 条 BLOCKED 线程，再用 JFR 量出「8 秒里累计等了 429.5 秒」，最后改代码复测到 5 毫秒。
中间还记了两个容易被误判的场景：CPU 打满时锁等待会被一起放大、p95 高但请求全堆在线程池队列里——这两种情况下改锁是白改。
文里的每个数字都是本机（Apple M1 Pro / JDK 25）跑出来的，原始输出贴在对应位置；跑不出来的地方会直说。

实验环境与口径

机器与 JDK

$ java -version
java version "25" 2025-09-16 LTS
Java(TM) SE Runtime Environment (build 25+37-LTS-3491)
Java HotSpot(TM) 64-Bit Server VM (build 25+37-LTS-3491, mixed mode, sharing)

$ sysctl -n machdep.cpu.brand_string hw.ncpu hw.memsize kern.osversion
Apple M1 Pro
10
17179869184
25G83

机器上另外装了 JDK 21.0.8，最后一节对照版本差异时用得到：

$ /Library/Java/JavaVirtualMachines/jdk-21.jdk/Contents/Home/bin/java -version
java version "21.0.8" 2025-07-15 LTS
Java(TM) SE Runtime Environment (build 21.0.8+12-LTS-250)
Java HotSpot(TM) 64-Bit Server VM (build 21.0.8+12-LTS-250, mixed mode, sharing)

服务端、压测端、JFR 分析全部用 JDK 自带工具（java/javac/jcmd/jfr），没有引入任何第三方压测框架或诊断工具。

被测服务

LockServer 只有一个接口 /query?k=<key>：每个请求要先把结果累加进一张共享统计表（需要互斥的部分，微秒级），同时还要做一次耗时 20ms 的下游查询（用 Thread.sleep(20) 模拟 JDBC / HTTP 调用）。同一个类用 --mode= 切换五种写法：

static final Object GLOBAL = new Object();
static final Map<String, long[]> STATS = new HashMap<>();
static final Object[] STRIPES = new Object[8];

private static void handle(HttpExchange exchange, String mode, int downstreamMs, int cpuMicros) throws IOException {
    String key = keyOf(exchange);
    long t0 = System.nanoTime();
    try {
        switch (mode) {
            case "broken" -> {
                synchronized (GLOBAL) {
                    Util.sleep(downstreamMs);
                    Util.merge(STATS, key, System.nanoTime() - t0);
                }
            }
            case "fixed" -> {
                Util.sleep(downstreamMs);
                synchronized (GLOBAL) {
                    Util.merge(STATS, key, System.nanoTime() - t0);
                }
            }
            case "keyed" -> {
                Object lock = STRIPES[Math.floorMod(key.hashCode(), STRIPES.length)];
                synchronized (lock) {
                    Util.sleep(downstreamMs);
                    Util.merge(STATS, key, System.nanoTime() - t0);
                }
            }
            case "cpu" -> {
                Util.burnCpu(cpuMicros);
                synchronized (GLOBAL) {
                    Util.merge(STATS, key, System.nanoTime() - t0);
                }
            }
            case "queue" -> {
                Util.sleep(downstreamMs);
                synchronized (GLOBAL) {
                    Util.merge(STATS, key, System.nanoTime() - t0);
                }
            }
            default -> throw new IllegalArgumentException("unknown mode " + mode);
        }
        byte[] body = "OK\n".getBytes();
        exchange.getResponseHeaders().set("Content-Type", "text/plain");
        exchange.sendResponseHeaders(200, body.length);
        try (OutputStream out = exchange.getResponseBody()) {
            out.write(body);
        }
    } catch (Exception e) {
        exchange.sendResponseHeaders(500, -1);
    } finally {
        exchange.close();
    }
}

broken 是症状版：一次下游调用被锁保护着，于是所有请求在锁上排队。fixed 把下游调用挪到锁外，锁里只剩统计表更新。keyed 是另一种修法：临界区里的昂贵操作不动，改成按 key 分成 8 把锁。cpu 和 queue 没有任何长临界区，后面单独讲。

merge 就是往 HashMap 里累加，微秒级：

static void merge(Map<String, long[]> stats, String key, long deltaNanos) {
    long[] v = stats.get(key);
    if (v == null) {
        v = new long[2];
        stats.put(key, v);
    }
    v[0] += deltaNanos;
    v[1]++;
}

HTTP 层是 com.sun.net.httpserver.HttpServer，线程池 Executors.newFixedThreadPool(200)（queue 场景另说），监听队列 8192。

压测客户端与口径

LoadClient 是手写的：固定并发数的平台线程，每个线程持有一条 keep-alive 长连接，串行发请求并记录每条请求的端到端延迟。参数与默认值：

int port = 8100;
int concurrency = 64;
int warmupMs = 1000;
int durationMs = 5000;
int keys = 8;              // 请求里的 k 在 0..keys-1 之间轮转
long[] samples = new long[2_000_000];

统一口径：预热 1 秒（不计入统计），统计窗口 5 秒，窗口结束后等在途请求收尾。所有对比都在**同一台机器、同一并发（64）、同一 key 数（8）**下进行，每档跑 3 次。

压测期间机器不空：uptime 读数从 3.90 涨到 12.00，其中大部分是本次实验自己造成的（64 条客户端线程 + 最多 200 条服务端线程挤在 10 个核上）。因此每个数据点取 3 次的中位数，并且只做横向对比，不把绝对数字当成这台机器的上限。

先量一个基线：sleep(20) 实际睡多久

「20ms 的下游调用」到底占多少时间，决定了后面所有数字的量级：

$ java -cp classes SleepAccuracy
sleep(20): avg=26.644ms min=20.061ms max=30.082ms
sleep(20): avg=26.888ms min=20.039ms max=31.683ms
sleep(20): avg=26.632ms min=20.167ms max=30.084ms

（一次 java 连跑 3 轮，每轮 200 次；实验后期重跑一次是 26.953 / 27.134 / 27.023ms。）

单线程下 sleep(20) 平均 26.8ms，多出来的 6.8ms 是定时器精度与线程唤醒调度。记住这个数：一个把「20ms 下游调用」整段包住的全局锁，吞吐上限就是 1 / 0.0268 ≈ 37 QPS，跟线程池多大、CPU 有多少核都没关系。

第一步：把症状跑出来

broken 模式跑三次：

$ ./run.sh
=== CASE broken (mode=broken pool=200 executor=platform settings=monitor.jfc) pid=34667
RESULT tag=broken concurrency=64 keys=8 windowMs=5003 requests=208 issuedTotal=313 errors=0 qps=41.6 p50=1533.62ms p95=1563.66ms p99=1566.50ms max=1569.56ms mean=1507.19ms
RESULT tag=broken concurrency=64 keys=8 windowMs=5001 requests=208 issuedTotal=313 errors=0 qps=41.6 p50=1539.30ms p95=1560.20ms p99=1561.20ms max=1561.57ms mean=1513.77ms
RESULT tag=broken concurrency=64 keys=8 windowMs=5005 requests=208 issuedTotal=313 errors=0 qps=41.6 p50=1536.46ms p95=1555.66ms p99=1556.38ms max=1557.36ms mean=1508.70ms
STATS mode=broken requests=939 processCpuMs=1750 cpuAfterStartMs=1655 cpuUsPerRequest=1763.3

三个数字：

• QPS 卡在 41.6，三次一模一样；
• p50 1536ms、p95 1560ms —— 延迟分布窄得像一把刀，说明所有请求经历的是同一件事；
• 进程 CPU 每请求 1763µs，也就是说服务几乎没在算，时间都花在等待上。

41.6 QPS 与前面算的 37 QPS 上限同一量级（反推临界区持有时间 24.0ms，比单线程测的 26.8ms 略短，差的 3ms 来自定时器唤醒与调度）。p50 1536ms 也能量出来：64 条并发一起抢一把锁，锁一释放就有一条线程拿走并再持有 24ms，排在队尾的那条要等 63 × 24ms ≈ 1512ms。实测 p50 = 1536ms，对得上。

一个「下游 20ms」的接口变成 1.5 秒，而机器 CPU 只用了 25%（后面量到的数），这就是锁竞争的典型形状：吞吐由临界区长度决定，多出来的并发全部变成排队延迟。

第二步：线程 dump 找 BLOCKED

抓 dump

服务是被压着的时候抓的，窗口中间取一次快照：

$ jcmd 34667 Thread.print -l > broken-rep1.dump.txt

63 条线程在等同一把锁

$ grep -c 'java.lang.Thread.State: BLOCKED' broken-rep1.dump.txt
63
$ grep -o 'waiting to lock <0x[0-9a-f]*>' broken-rep1.dump.txt | sort | uniq -c
  63 waiting to lock <0x000000030d608110>

64 条并发请求，1 条在临界区里，剩下 63 条全部 BLOCKED，而且全部指向同一个地址。任意一条的栈长这样：

"pool-1-thread-104" #144 [128771] prio=5 os_prio=31 cpu=0.23ms elapsed=1.52s tid=0x000000071eca3000 nid=128771 waiting for monitor entry
   java.lang.Thread.State: BLOCKED (on object monitor)
	at LockServer.handle(LockServer.java:109)
	- waiting to lock <0x000000030d608110> (a java.lang.Object)
	at LockServer.lambda$main$0(LockServer.java:74)
	at LockServer$$Lambda/0x0000780001040210.handle(Unknown Source)
	at com.sun.net.httpserver.Filter$Chain.doFilter(jdk.httpserver@25/Filter.java:98)
	at sun.net.httpserver.AuthFilter.doFilter(jdk.httpserver@25/AuthFilter.java:76)
	at com.sun.net.httpserver.Filter$Chain.doFilter(jdk.httpserver@25/Filter.java:101)
	at sun.net.httpserver.ServerImpl$Exchange$LinkHandler.handle(jdk.httpserver@25/ServerImpl.java:915)
	at com.sun.net.httpserver.Filter$Chain.doFilter(jdk.httpserver@25/Filter.java:98)
	at sun.net.httpserver.ServerImpl$Exchange.run(jdk.httpserver@25/ServerImpl.java:891)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@25/ThreadPoolExecutor.java:1090)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@25/ThreadPoolExecutor.java:614)
	at java.lang.Thread.runWith(java.base@25/Thread.java:1487)
	at java.lang.Thread.run(java.base@25/Thread.java:1474)

BLOCKED (on object monitor) + waiting to lock <地址> 就是「在等锁，不是在等 IO、不是在等信号」。栈顶直接落在自己代码的 LockServer.handle，这一层就把「业务代码里的锁」和「线程池 / HTTP 层的等待」区分开了——后者出现在 LinkedBlockingQueue.take、park 之类的帧里，状态是 WAITING/TIMED_WAITING，不是 BLOCKED。

持有者在干什么

同一份 dump 里，唯一锁上该地址的那条线程：

"pool-1-thread-103" #143 [129027] prio=5 os_prio=31 cpu=0.33ms elapsed=1.55s tid=0x000000071eca2800 nid=129027 sleeping
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleepNanos0(java.base@25/Native Method)
	at java.lang.Thread.sleepNanos(java.base@25/Thread.java:509)
	at java.lang.Thread.sleep(java.base@25/Thread.java:540)
	at LockServer$Util.sleep(LockServer.java:169)
	at LockServer.handle(LockServer.java:109)
	- locked <0x000000030d608110> (a java.lang.Object)

- locked <0x000000030d608110> 与上面 63 条的 - waiting to lock 是同一个地址，两边一对就形成了完整证据链：谁持有、持有多久、谁在等。这条线程的行号是 LockServer.java:109，就是 broken 里那行 Util.sleep(downstreamMs)——20ms 的下游调用正躺在临界区里。

线程数也是信号

线程 dump 只能看瞬时状态，线程总数用 JFR 的 thread-count 视图更省事：

$ jfr view thread-count broken-rep1.jfr
Time         Active Threads   Daemon Threads   Accumulated Threads   Peak Threads
---------- ---------------- ---------------- --------------------- --------------
16:10:19                108                9                   108            108
16:10:20                151                9                   151            151
16:10:21                192                9                   192            192
16:10:22                211                9                   211            211
16:10:23                211                9                   211            211

峰值 211 条平台线程：进程里线程暴涨本身就说明请求堆积了（客户端 64 并发，服务端却开了 211 条线程来对付它）。这个数字在后面的「排队」场景里会形成一个很干净的对照。

第三步：JFR 把等待量出来

线程 dump 能证明「在等锁」，但证明不了「等了多久、值不值得改」。这一步交给 JFR。

先确认事件是开着的

JFR 的锁事件不是「录了就有」，默认 settings 里它们的阈值由 locking-threshold 控制：

$ grep -n -A3 'jdk.JavaMonitorEnter' $JAVA_HOME/lib/jfr/profile.jfc
86:    <event name="jdk.JavaMonitorEnter">
87-      <setting name="enabled">true</setting>
88-      <setting name="stackTrace">true</setting>
89-      <setting name="threshold" control="locking-threshold">10 ms</setting>

$ grep -n 'name="locking-threshold"' $JAVA_HOME/lib/jfr/profile.jfc
1189:      <text name="locking-threshold" label="Locking Threshold" contentType="timespan" minimum="0 s">10 ms</text>

事件是开着的，但阈值 10ms——只有超过 10ms 的等待才会被记录（default.jfc 里这个值是 20ms）。一次只等 30µs 的争用在这个配置下根本不会出现在录制里。

所以先用 jfr configure 基于 profile.jfc 生成一份自己的设置，把阈值压到 0：

$ jfr configure --input $JAVA_HOME/lib/jfr/profile.jfc --output monitor.jfc \
    jdk.JavaMonitorEnter#enabled=true jdk.JavaMonitorEnter#threshold=0 jdk.JavaMonitorEnter#stackTrace=false \
    jdk.JavaMonitorWait#enabled=true jdk.JavaMonitorWait#threshold=0 jdk.JavaMonitorWait#stackTrace=false \
    jdk.ThreadPark#enabled=true jdk.ThreadPark#threshold=0 jdk.ThreadPark#stackTrace=false \
    jdk.VirtualThreadPinned#enabled=true jdk.VirtualThreadPinned#threshold=0
Configuration written successfully to:
/private/tmp/lockcheck/monitor.jfc

$ grep -n -A3 'jdk.JavaMonitorEnter' monitor.jfc
86:  <event name="jdk.JavaMonitorEnter">
87-    <setting name="enabled">true</setting>
88-    <setting name="stackTrace">false</setting>
89-    <setting name="threshold" control="locking-threshold">0</setting>

（stackTrace=false 是为了让事件体积可控：只统计次数与时长，只有需要辨认「这是哪把锁」时才把栈打开——后面识别调用点时会打开一次。另外注意第一行 enabled：jdk.JavaMonitorEnter 在 profile.jfc 里本来就是 true，会藏起证据的是阈值，不是开关。）

默认阈值会漏掉什么

写个最小验证：4 条线程各对一个全局锁做 10 万次自增，一共 40 万次 synchronized 进入，每次临界区只有几十纳秒。

$ java -cp classes -XX:StartFlightRecording=filename=micro-profile.jfr,settings=$JAVA_HOME/lib/jfr/profile.jfc MicroContention
MicroContention threads=4 enters=400000 elapsedMs=37 counter=400000

$ jfr summary micro-profile.jfr | grep -i -e JavaMonitorEnter -e ThreadPark
 jdk.JavaMonitorEnter                        0             0
 jdk.ThreadPark                              0             0

$ java -cp classes -XX:StartFlightRecording=filename=micro-threshold0.jfr,settings=monitor.jfc MicroContention
MicroContention threads=4 enters=400000 elapsedMs=29 counter=400000

$ jfr summary micro-threshold0.jfr | grep -i -e JavaMonitorEnter -e ThreadPark
 jdk.JavaMonitorEnter                     1906         34957
 jdk.ThreadPark                              0             0

同一份代码、同样 40 万次进入：默认 profile.jfc 记到 0 条，阈值 0 的配置记到 1906 条。差一个数量级还多。

被记下来的单条事件长这样：

jdk.JavaMonitorEnter {
  startTime = 16:16:32.542 (2026-09-15)
  duration = 0.00113 ms
  monitorClass = java.lang.Object (classLoader = bootstrap)
  previousOwner = "Thread-0" (javaThreadId = 29)
  address = 0x766D3E140
  eventThread = "Thread-1" (javaThreadId = 30)
}

duration 1.13µs，previousOwner 还写着抢到锁的是谁。这类事件在默认配置下全军覆没。

「用 JFR 看有没有锁竞争」这件事，必须先确认阈值。默认的 10ms 阈值意味着录制报告「没有锁竞争」时，你只能得出「没有超过 10ms 的锁竞争」，微秒级的争用照样可以把吞吐拉低一个数量级。

录制口径

压测窗口内录制，用 jcmd 在客户端启动前后卡住范围：

$ jcmd <pid> JFR.start name=rec settings=monitor.jfc filename=broken-5s.jfr
$ java -cp classes LoadClient --port=8101 --concurrency=64 --warmup=1000 --duration=5000 --keys=8 --tag=broken-5s
$ jcmd <pid> JFR.stop name=rec

下面这张表里的锁数据全部来自这类录制，它跟前面的 QPS 表不是同一批数据，不要混着读：录制（尤其把 stackTrace 打开时）本身有开销，同一场景录着跑比不录慢 7% 左右——broken 从 41.6 QPS 掉到 36.8，fixed 从 2756 QPS 掉到 2549。锁的计数与时长不受影响，吞吐和延迟只引用不录制的 3 次中位数。

jfr summary

$ jfr summary broken-5s.jfr
 Version: 2.1
 Chunks: 1
 Start: 2026-09-15 08:19:48 (UTC)
 Duration: 8 s

 Event Type                              Count  Size (bytes)
=============================================================
 jdk.JavaMonitorEnter                      397          9121
 jdk.ThreadSleep                           284          5225
 jdk.ThreadPark                            149          5871
 jdk.JavaMonitorWait                        46          1083
 jdk.ExecutionSample                        20           205
 jdk.JavaMonitorStatistics                   2            16
 ...

（Size (bytes) 是事件体积，不是时长——想看时长得用 jfr print 或 jfr view；... 是省略的其余事件类型。）

录制覆盖预热 + 统计窗口共 8 秒，jdk.JavaMonitorEnter 397 条。这里有个坑：397 条里混着 JVM 自己的锁（类加载、JFR 内部记录器、HttpServer 的上下文表），不能直接当成业务锁的代价。

按调用点聚合

把栈打开再录一次，按栈顶方法分组，就能把「业务锁」单独拎出来：

$ jfr view contention-by-site fixed-5s.jfr | grep LockServer
LockServer.handle(HttpExchange, String, int, int)                                            56   0.0900 ms    0.474 ms

修好之后业务锁那一行只有 56 条、单次平均 0.09ms。同样的方法作用在 broken 上：

$ jfr view contention-by-site broken-5s.jfr | grep LockServer
StackTrace                                                              Count        Avg.        Max.
LockServer.handle(HttpExchange, String, int, int)                         283      1.52 s      1.76 s

把次数、累计等待、单次平均、最长等待拉平成一张表（都是 5 秒窗口、64 并发、stackTrace=on 的录制）：

场景	业务锁事件数	累计等待	单次平均	最长
broken	283	429500.7ms	1517.67ms	1756.54ms
fixed	56	5.0ms	0.09ms	0.47ms
keyed	1836	340559.6ms	185.49ms	210.25ms
cpu	946	49585.8ms	52.42ms	150.99ms
queue	7	0.1ms	0.016ms	0.045ms

broken 那一行是本次定位的核心证据：8 秒的录制窗口里，业务锁上的累计等待 429.5 秒。换算成「同一时刻平均有多少条线程卡在这把锁上」就是 429500.7ms / 8000ms ≈ 53.7 条——64 条并发里有 54 条在排队。修复后（fixed）是 5.0ms，即 0.0006 条。

另一个要小心的读法：累计等待时长衡量的是「有多少线程在等」，不是「问题有多严重」。keyed 的累计等待 340.6 秒和 broken 的 429.5 秒是同一量级，但它的 QPS 是 333.6（8 倍于 41.6）——因为客户端始终把 64 条线程全部压满，等待总时长由「客户端并发数 × 窗口时长」封顶，谁也超不过。要看改善幅度，得看单次平均等待（1517.67ms → 185.49ms）和吞吐。

第四步：修复与复测

修复思路

broken 的临界区里除了一行 v[0] += delta; v[1]++，还压着一次 20ms 的下游调用。三种改法：

1. 把阻塞移出锁（fixed）：下游调用照做，锁只保护统计表更新。适用于「临界区里本来只需要保护共享状态」的绝大多数情况。
2. 按 key 分段锁（keyed）：临界区里的昂贵操作确实需要互斥（比如同一个 key 的聚合必须串行），那就把一把锁换成 N 把，不同 key 互不阻塞。
3. 读写分离 / ConcurrentHashMap 换掉 HashMap：本例的统计表用 LongAdder 之类就能完全去锁，但那样就测不出「短临界区」的残留争用了，所以保留 synchronized 作为对照。

复测数据（各 3 次）

=== CASE fixed (mode=fixed pool=200 executor=platform settings=monitor.jfc) pid=35030
RESULT tag=fixed concurrency=64 keys=8 windowMs=5003 requests=13745 issuedTotal=16328 errors=0 qps=2747.4 p50=23.44ms p95=25.30ms p99=25.63ms max=45.11ms mean=23.25ms
RESULT tag=fixed concurrency=64 keys=8 windowMs=5004 requests=13792 issuedTotal=16560 errors=0 qps=2756.0 p50=23.41ms p95=25.30ms p99=25.56ms max=57.42ms mean=23.25ms
RESULT tag=fixed concurrency=64 keys=8 windowMs=5001 requests=13841 issuedTotal=16640 errors=0 qps=2767.8 p50=23.18ms p95=25.24ms p99=25.44ms max=53.99ms mean=23.11ms
STATS mode=fixed requests=49528 processCpuMs=7247 cpuAfterStartMs=7155 cpuUsPerRequest=144.5

=== CASE keyed (mode=keyed pool=200 executor=platform settings=monitor.jfc) pid=35352
RESULT tag=keyed concurrency=64 keys=8 windowMs=5004 requests=1675 issuedTotal=2071 errors=0 qps=334.7 p50=191.29ms p95=198.63ms p99=200.38ms max=208.78ms mean=191.15ms
RESULT tag=keyed concurrency=64 keys=8 windowMs=5004 requests=1668 issuedTotal=2063 errors=0 qps=333.3 p50=191.63ms p95=200.03ms p99=210.58ms max=222.26ms mean=191.97ms
RESULT tag=keyed concurrency=64 keys=8 windowMs=5003 requests=1669 issuedTotal=2064 errors=0 qps=333.6 p50=191.66ms p95=199.77ms p99=215.26ms max=223.19ms mean=192.02ms
STATS mode=keyed requests=6198 processCpuMs=3453 cpuAfterStartMs=3358 cpuUsPerRequest=541.9

场景	QPS（3 次）	QPS 中位	p50 中位	p95 中位	进程 CPU/请求
broken	41.6 / 41.6 / 41.6	41.6	1536.46ms	1560.20ms	1763µs
fixed	2747.4 / 2756.0 / 2767.8	2756.0	23.41ms	25.30ms	145µs
keyed	334.7 / 333.3 / 333.6	333.6	191.63ms	200.03ms	542µs
cpu	1251.7 / 1278.0 / 1378.4	1278.0	41.71ms	103.62ms	6099µs
queue（池 4）	165.2 / 165.6 / 165.6	165.6	386.91ms	395.95ms	727µs
queue（池 64）	2774.9 / 2763.1 / 2765.2	2765.2	23.31ms	25.25ms	135µs

• fixed 对 broken：吞吐 66 倍（41.6 → 2756），p50 从 1536ms 回到 23.41ms，与「20ms 下游调用 + 3ms 调度开销」的裸服务时间一致。
• fixed 的 2756 QPS 不是服务端上限，是客户端上限：64 条并发线程、每条 23.4ms 一个来回，64 / 0.0234 ≈ 2735 QPS。想测更高得加客户端并发。
• keyed 是 334 QPS，正好是 broken 的 8 倍，与 8 段锁一一对应；p50 从 1536ms 降到 191ms（8 条客户端排队 × 24ms，对得上）。
• 进程 CPU 每请求从 1763µs 掉到 145µs：等待不是免费的，被唤醒、失败自旋、线程创建都要花 CPU。

修复后的 JFR 对比

同一个 5 秒窗口、同样 64 并发，业务锁上的 jdk.JavaMonitorEnter：

场景     调用点                 事件数      累计等待ms    单次平均ms    最长ms
broken   LockServer.handle        283        429500.7       1517.67    1756.537
fixed    LockServer.handle         56             5.0          0.09       0.474

• 事件数：283 → 56；
• 累计等待：429500.7ms → 5.0ms（差 85900 倍）；
• 单次平均：1517.67ms → 0.09ms；
• 最长等待：1756.54ms → 0.47ms。

替换成「每次请求被阻塞多少次」更直观：broken 是 283 / 184 = 1.54 次/请求，fixed 是 56 / 12760 = 0.0044 次/请求，350 倍。

修复后还有 56 次事件、5ms 累计等待——不是 0。短临界区依然会有微秒级的争用，这属于正常现象；判断标准是它有没有吃掉可观测的吞吐或延迟，而不是「必须归零」。

分段锁把自己的等待摊开了

keyed 版本在线程 dump 里的样子，是这次排查里最能说明「分而治之」的一张图：

$ grep -c 'java.lang.Thread.State: BLOCKED' keyed-rep1.dump.txt
56
$ grep -o 'waiting to lock <0x[0-9a-f]*>' keyed-rep1.dump.txt | sort | uniq -c
   7 waiting to lock <0x000000030d608250>
   7 waiting to lock <0x000000030d608af8>
   7 waiting to lock <0x000000030d618128>
   7 waiting to lock <0x000000030d620288>
   7 waiting to lock <0x000000030d6281b0>
   7 waiting to lock <0x000000030d6286e8>
   7 waiting to lock <0x000000030d647dd0>
   7 waiting to lock <0x000000030d6e7140>

同一次压测，broken 是「63 条等 1 个地址」，keyed 是「56 条等 8 个地址、每个 7 条」。JFR 侧的数据也对得上：1836 条事件被 8 把锁均分（每把约 258 条、累计 42.4 秒），单次平均等待从 1517.67ms 降到 185.49ms。

注意 keyed 的累计等待（340.6 秒）几乎没比 broken（429.5 秒）少——客户端 64 条线程全程被压满，等待总量是守恒的。改变的是等待被摊到 8 条独立的队列上，每条约 1/8 长。

别用默认配置验证修复

修复后的等待都在 1ms 以下，而默认 profile.jfc 的阈值是 10ms。同一份 fixed 代码，两个设置录两次：

# 默认 profile.jfc（locking-threshold = 10 ms）
$ jfr view contention-by-site fixedstock-rep1.jfr | grep -c LockServer
0

# threshold = 0 的 monitor.jfc
$ jfr view contention-by-site fixed-5s.jfr | grep LockServer
LockServer.handle(HttpExchange, String, int, int)                                            56   0.0900 ms    0.474 ms

用默认设置去验证，「修复后残留争用」这一栏会得到 0，看起来像彻底消除了。真实情况是 56 次、5ms 的残留——量级很小，但它存在，而报告的 0 是阈值过滤出来的假象。

看起来像锁竞争、但不是的两种情况

一、CPU 打满：同一个锁，等待时长差 582 倍

cpu 模式的 handler 不做任何下游调用，改为每个请求在锁外烧 20ms CPU，只在最后进锁更新统计表：

=== CASE cpu (mode=cpu pool=200 executor=platform) pid=35676
RESULT tag=cpu concurrency=64 keys=8 windowMs=5004 requests=6263 issuedTotal=7090 errors=0 qps=1251.7 p50=43.69ms p95=104.87ms p99=153.60ms max=229.15ms mean=51.17ms
RESULT tag=cpu concurrency=64 keys=8 windowMs=5005 requests=6396 issuedTotal=7750 errors=0 qps=1278.0 p50=41.71ms p95=103.62ms p99=130.74ms max=235.51ms mean=50.13ms
RESULT tag=cpu concurrency=64 keys=8 windowMs=5005 requests=6899 issuedTotal=8185 errors=0 qps=1378.4 p50=40.59ms p95=86.06ms p99=129.27ms max=203.83ms mean=46.22ms
STATS mode=cpu requests=23025 processCpuMs=140512 cpuAfterStartMs=140419 cpuUsPerRequest=6098.6

症状是「QPS 只有 1278、p95 86~105ms」，跟锁竞争一样难看。而且 JFR 里能看到锁等待：

指标	cpu 场景	fixed 场景（同一段临界区）
业务锁事件数	946	56
累计等待	49585.8ms	5.0ms
单次平均	52.42ms	0.09ms
最长	150.99ms	0.47ms

同一条 synchronized (GLOBAL) { merge(...) }，在 cpu 场景里单次平均等待 52.42ms，在 fixed 场景里 0.09ms，582 倍。临界区代码一模一样，merge 都是微秒级——等待不是临界区长度造成的。

区别在别处：

$ jfr view cpu-load cpu-rep1.jfr | grep -e 'JVM User' -e 'Machine Total'
JVM User (Minimum): 71.29%
JVM User (Average): 75.44%
JVM User (Maximum): 76.83%
Machine Total (Minimum): 98.90%
Machine Total (Average): 99.78%
Machine Total (Maximum): 100.00%

$ jfr view cpu-load broken-rep1.jfr | grep -e 'JVM User' -e 'Machine Total'
JVM User (Minimum): 0.30%
JVM User (Average): 0.43%
JVM User (Maximum): 0.50%
Machine Total (Minimum): 22.82%
Machine Total (Average): 25.32%
Machine Total (Maximum): 30.12%

$ jfr view hot-methods cpu-rep1.jfr
Method                                                                                                  Samples Percent
LockServer$Util.burnCpu(int)                                                                                519  90.58%
LockServer.handle(HttpExchange, String, int, int)                                                            13   2.27%

服务进程自己占 75.44% 的整机 CPU（锁竞争那档只有 0.43%，机器那 25% 是压测客户端烧的），90.58% 的采样落在业务方法 burnCpu 上，进程 CPU 每请求 6099µs（fixed 是 145µs）。

这里的机制是调度饥饿：锁的持有者被 64 条抢 CPU 的线程挤出时间片，于是「释放锁」这个动作本身被推迟，等待者只能干等。这次 dump 的状态分布是 BLOCKED 25 / RUNNABLE 35 / WAITING(parking) 150（另有 5 条卡在别的监视器上），与锁竞争场景「63 条 BLOCKED 全部指向同一个地址」的形状完全不同。

两种场景的判断分界：CPU 打满时，jdk.CPULoad 会顶到 100%、进程自己的 CPU 占用（JVM User）是 75.44% 对 0.43% 的差距、hot-methods 指向业务计算代码，而锁等待只是这些 CPU 饥饿的副产物。修法是给 CPU 密集的活单独限并发（或换独立线程池），不是拆锁——把锁拆了，等待时间只会从「等锁」变成「等 CPU」。

（本例的 burnCpu 用 System.nanoTime() 卡 20ms 的墙钟时间，所以每请求实际分到的 CPU 是 6099µs：64 条线程抢 10 个核，谁都拿不满。）

二、p95 高，但请求堆在线程池队列里

queue 模式的 handler 里没有任何长临界区（sleep 在锁外，锁里只有 merge），但把服务端线程池从 200 缩到 4：

=== CASE queue4 (mode=queue pool=4) pid=35987
RESULT tag=queue4 concurrency=64 keys=8 windowMs=5001 requests=826 issuedTotal=1046 errors=0 qps=165.2 p50=388.14ms p95=397.49ms p99=399.99ms max=401.55ms mean=388.48ms
RESULT tag=queue4 concurrency=64 keys=8 windowMs=5005 requests=829 issuedTotal=1057 errors=0 qps=165.6 p50=385.66ms p95=395.39ms p99=398.65ms max=400.11ms mean=386.10ms
RESULT tag=queue4 concurrency=64 keys=8 windowMs=5005 requests=829 issuedTotal=1056 errors=0 qps=165.6 p50=386.91ms p95=395.95ms p99=398.02ms max=401.28ms mean=386.98ms
STATS mode=queue requests=3159 processCpuMs=2386 cpuAfterStartMs=2295 cpuUsPerRequest=726.5

p50 388ms、p95 396ms，跟 broken 的 1536ms 是同一量级的问题。但看证据：

$ grep -c 'java.lang.Thread.State: BLOCKED' queue4-rep1.dump.txt
0

$ grep -c '"pool-1-thread' queue4-rep1.dump.txt
4

$ jfr view thread-count queue4-rep1.jfr
Time         Active Threads   Daemon Threads   Accumulated Threads   Peak Threads
---------- ---------------- ---------------- --------------------- --------------
16:11:44                 15                9                    15             15
16:11:45                 15                9                    15             15

• 线程 dump 里 BLOCKED 是 0；
• 整个 JVM 只有 15 条线程（锁竞争那档是 211 条），池子里就 4 条 handler 线程，全在 TIMED_WAITING (sleeping)；
• 业务锁那一行：7 次事件、累计 0.1ms，等于没有争用。

请求去哪了？堆在 ThreadPoolExecutor 的队列里——那是一个 LinkedBlockingQueue 里的 Runnable，线程 dump 看不见它（队列不是线程），JFR 的锁事件也看不见它（排队不是锁）。64 条连接、4 个槽位，每个请求 sleep(20) 的实际耗时 24ms，所以 p50 就是 16 × 24ms ≈ 384ms。

把池子改回 64（不改一行 handler 代码）：

=== CASE queue64 (mode=queue pool=64) pid=36313
RESULT tag=queue64 concurrency=64 keys=8 windowMs=5005 requests=13888 issuedTotal=16510 errors=0 qps=2774.9 p50=23.24ms p95=25.27ms p99=25.44ms max=33.07ms mean=23.08ms
RESULT tag=queue64 concurrency=64 keys=8 windowMs=5003 requests=13823 issuedTotal=16610 errors=0 qps=2763.1 p50=23.33ms p95=25.25ms p99=25.41ms max=47.64ms mean=23.16ms
RESULT tag=queue64 concurrency=64 keys=8 windowMs=5000 requests=13827 issuedTotal=16641 errors=0 qps=2765.2 p50=23.31ms p95=25.25ms p99=25.43ms max=42.30ms mean=23.14ms
STATS mode=queue requests=49761 processCpuMs=6820 cpuAfterStartMs=6724 cpuUsPerRequest=135.1

165.6 → 2765.2 QPS，p50 386.91 → 23.31ms。这是容量问题，拆锁拆到天亮也不会好。

两种误判的共同点：先看线程状态构成，再看 JFR 的单次平均等待，最后才看哪个监视器排在累计等待榜首。只有「BLOCKED 集中在少数几个监视器上、单次平均等待跟临界区长度同量级」时才值得动锁代码。

JDK 21 与 JDK 25：synchronized 不再固定载体线程

同一个 broken 服务换成虚拟线程执行器（Executors.newVirtualThreadPerTaskExecutor()），压测并发降到 4（这样载体线程（默认 10 条）不会被并发数本身卡住，看到的差异只来自 pin），在 JDK 21 和 JDK 25 上各跑一次。

开关对照

$ JDK21/bin/java -Djdk.tracePinnedThreads=full -cp out/classes21 LockServer --port=8163 --mode=broken --executor=virtual
VirtualThread[#35]/runnable@ForkJoinPool-1-worker-2 reason:MONITOR
    java.base/java.lang.VirtualThread$VThreadContinuation.onPinned(VirtualThread.java:199)
    java.base/jdk.internal.vm.Continuation.onPinned0(Continuation.java:393)
    java.base/java.lang.VirtualThread.parkNanos(VirtualThread.java:635)
    java.base/java.lang.VirtualThread.sleepNanos(VirtualThread.java:807)
    java.base/java.lang.Thread.sleep(Thread.java:507)
    LockServer$Util.sleep(LockServer.java:169)
    LockServer.handle(LockServer.java:109) <== monitors:1
    LockServer.lambda$main$0(LockServer.java:74)
    jdk.httpserver/com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:98)
    ...

$ JDK25/bin/java -Djdk.tracePinnedThreads=full -cp classes LockServer --port=8164 --mode=broken --executor=virtual
SERVER mode=broken executor=virtual pool=200 downstreamMs=20 port=8164
STATS mode=broken requests=229 processCpuMs=606 cpuAfterStartMs=459 cpuUsPerRequest=2007.5

JDK 21 上，<== monitors:1 直接把「你这行 synchronized 把载体线程按住了」指到 LockServer.handle(LockServer.java:109)。JDK 25 上加了同样的开关、跑同样的负载（229 个请求），整份日志只有上面两行——JDK 24 起该开关不再有效（JEP 491 移除了 synchronized 造成的 pinning，这个开关连同它所报告的机制一起退场）。

JDK 21 上那次 6 秒压测（232 个请求、4 并发）里，这个开关只打印了 1 次栈；JFR 在另一次 2 秒录制里记到了 88 次 pin 事件。它适合抓一次现场看一眼，不适合用来统计。

JFR 里的 pin 事件长得不一样

# JDK 21
jdk.VirtualThreadPinned {
  startTime = 16:16:37.087 (2026-09-15)
  duration = 16.0 ms
  eventThread = "" (javaThreadId = 35, virtual)
  stackTrace = [
    java.lang.VirtualThread.parkOnCarrierThread(boolean, long) line: 689
    java.lang.VirtualThread.parkNanos(long) line: 648
    java.lang.VirtualThread.sleepNanos(long) line: 807
    java.lang.Thread.sleep(long) line: 507
    LockServer$Util.sleep(int) line: 169
    ...
  ]
}

# JDK 25
jdk.VirtualThreadPinned {
  startTime = 16:16:42.779 (2026-09-15)
  duration = 0.933 ms
  blockingOperation = "Contended monitor enter"
  pinnedReason = "Freeze or preempt failed (2)"
  carrierThread = "ForkJoinPool-1-worker-3" (javaThreadId = 38)
  eventThread = "" (javaThreadId = 39, virtual)
  ...
}

	JDK 21.0.8	JDK 25
jdk.VirtualThreadPinned 事件数（同负载）	88	58
事件时长	16.0ms / 21.5ms	0.7µs ~ 0.996ms
栈里有 parkOnCarrierThread	有	无
pinnedReason	无此字段	Freeze or preempt failed (2) / VM call to ...<clinit> on stack
吞吐（4 并发，锁是瓶颈）	36.8 QPS	36.3 QPS

JDK 21 的 pin 持续时间和 sleep(20) 同量级，栈里 parkOnCarrierThread 说明载体线程被一起按住了——10 条载体对付 4 条并发请求时看不出来，一旦并发超过载体数就会变成容量天花板。JDK 25 剩下的 58 条全是亚毫秒级的「冻结/抢占失败」瞬时事件，不是「synchronized 按住载体」那个意思。

两边的吞吐几乎一样（36.8 vs 36.3），因为这里瓶颈是那把全局锁——pin 消耗的是载体线程数，不是单请求的执行速度；只有并发规模超过载体数、且任务真的需要并行时，它才会体现在吞吐上。

总结

• 一个锁住 20ms 下游调用的全局锁，把 64 并发的服务压到 41.6 QPS、p50 1536ms，而机器 CPU 只用了 25%。吞吐由临界区长度决定（1 / 0.0268s ≈ 37 QPS），并发数只决定排队长度（63 × 24ms ≈ 1512ms，实测 p50 1536ms）。
• 线程 dump 是最快的一层：BLOCKED (on object monitor) + waiting to lock <地址> 的线程数，与「等 IO / 等信号」的 WAITING、TIMED_WAITING 能直接分开。这次抓到 63 条等 1 个地址，持有者在同一地址上 - locked 且停在 LockServer.java:109。
• JFR 的锁事件要先用 jfr configure 改阈值再谈结论：profile.jfc 的 locking-threshold 是 10ms（default.jfc 是 20ms）。40 万次微秒级 synchronized 自增，默认配置记到 0 条，阈值调到 0 记到 1906 条。
• 用调用点（contention-by-site）而不是监视器地址来聚合，才能把业务锁从 JVM 内部的锁里摘出来。同一个 8 秒窗口里，broken 的应用锁累计等待 429.5 秒（平均 53.7 条线程卡在锁上），全量统计 397 条事件里混着类加载、HttpServer 上下文表等噪声。
• 把阻塞移出临界区后：QPS 41.6 → 2756（66 倍），p50 1536.46ms → 23.41ms，单次平均锁等待 1517.67ms → 0.09ms，累计等待 429500.7ms → 5.0ms，每次请求被阻塞 1.54 次 → 0.0044 次。
• 分段锁是另一条路：8 把锁把吞吐抬到 333.6 QPS（正好 8 倍），dump 里 56 条 BLOCKED 均分在 8 个地址上、每个 7 条，单次平均等待降到 185.49ms。累计等待总时长（340.6 秒）几乎没降：客户端被压满时等待总量守恒，它衡量的是「多少线程在等」而不是「问题多严重」。
• 验证修复别用默认配置：修复后的等待都在 1ms 以下，默认 10ms 阈值会把它们全部过滤掉，同一份代码会报出「0 次争用」。
• 误判一（CPU 打满）：同一个锁、同一段微秒级临界区，在 CPU 饱和场景里单次平均等待 52.42ms、累计 49.6 秒，在正常场景里是 0.09ms、5ms：582 倍差距来自调度饥饿，不是临界区长度。判断依据是 jdk.CPULoad 99.78% 与 hot-methods 里 90.58% 的采样落在业务计算上。
• 误判二（容量不足）：池子 4 条线程时 p50 388ms、p95 396ms，但 BLOCKED 是 0、整个 JVM 只有 15 条线程、应用锁累计等待 0.1ms，请求堆在 ThreadPoolExecutor 队列里，线程 dump 和锁事件都看不见。池子改回 64 后 2765 QPS、p50 23.31ms。
• 虚拟线程侧：同一个 synchronized 包着 sleep 的服务，JDK 21 记录到 88 次 pin（16.0/21.5ms，栈里有 parkOnCarrierThread），JDK 25 只剩 58 次亚毫秒级的「冻结失败」，-Djdk.tracePinnedThreads=full 在 JDK 25 上一条输出都没有（JEP 491，JDK 24）。两边吞吐相同（36.8 vs 36.3 QPS），因为瓶颈是锁，pin 消耗的是载体线程数而不是单请求速度。
• 全部数据来自单机压测（客户端与服务端共享 10 个核，压测期间 load average 3.90~12.00），结论的方向可信，绝对数字不要外推。

参考资料

• JEP 491: Synchronize Virtual Threads without Pinning — Status: Closed / Delivered，Release: 24
• jfr 命令（JDK 工具参考） — jfr configure、jfr summary、jfr print、jfr view
• jcmd 命令（JDK 工具参考） — Thread.print、JFR.start、JFR.stop
• jdk.jfr.events（Java SE 25 API） — JavaMonitorEnterEvent、VirtualThreadPinnedEvent
• Java 24: Thread Pinning Revisited — JDK 24 起 jdk.tracePinnedThreads 不再有效，改用 jdk.VirtualThreadPinned 事件

系列索引：Java 系列，语言特性与运行时的长文集