承接的问题
12.1 解决了「池子忙不忙」。紧接着的问题是「谁把池子占住了」。
构造一个 p99 劣化的场景：接口平均 40 ms，p99 从 60 ms 涨到 900 ms，CPU 只有 25%，线程池 4 个线程全部在工作。抓一份线程转储，能看到 3 个 BLOCKED (on object monitor)，但转储只说「此刻在等」，不说：
- 等了多久，是刚撞上还是已经卡了 800 ms；
- 等的是哪个请求——线程是复用的，
loan-worker-2上午处理过几百个请求； - 锁被谁持有，持有者的那段临界区是不是本来就该 200 ms。
JFR（3.1）能回答「等了多久」，但它有阈值和事件量；转储（3.3）能回答「此刻卡在哪一行」，但它是一张照片；调用链能回答「这个线程正在服务哪个请求」，但需要请求上下文。本节把三者拼成一条能落日志的证据链：状态来自 ThreadMXBean，归属来自请求上下文注册表，时长来自连续两次扫描的差值。
先钉死一个限制：ThreadLocal 是线程私有的。监控线程无法读取 loan-worker-2 的 ThreadLocal，这不是 API 没找对，而是设计如此。想要跨线程看到「这个 worker 正在服务哪个请求」，必须在设置 ThreadLocal 的同时，往一个所有线程可见的注册表里写一份。
ThreadMXBean 能给什么、给不出什么
java.lang.management.ThreadMXBean 提供了三档接口：
ThreadInfo info = mx.getThreadInfo(threadId); // 单线程，默认栈深度
ThreadInfo[] all = mx.getThreadInfo(ids, 8); // 批量，指定栈深度
ThreadInfo[] dump = mx.dumpAllThreads(true, true); // 锁与 synchronizer 信息
单条 ThreadInfo 里对本节有用的字段：
| 字段 | 含义 | 注意事项 |
|---|---|---|
getThreadState() | RUNNABLE / BLOCKED / WAITING / TIMED_WAITING | 只反映取快照那一刻 |
getStackTrace() | 栈帧 | 深度受 maxDepth 限制，0 表示不要栈 |
getLockName() | 阻塞在哪个监视器 | 同进程内地址可关联，跨进程无意义 |
getLockOwnerId() / getLockOwnerName() | 持有者 | 监视器可能已经交接，只代表此刻 |
getBlockedCount() | 累计进入 BLOCKED 的次数 | 是次数，不是本次时长 |
getBlockedTime() | 累计阻塞毫秒数 | 默认关闭，关闭时返回 -1 |
getWaitedCount() / getWaitedTime() | wait 的累计次数与时间 | 与 BLOCKED 是两套口径 |
本机实测了两个容易写错的点：
contentionEnabled=false supported=true
cpuEnabled=true supported=true
virtualThreadCountInMXBean=false platformThreads=9
blockedTimeOfMain=-1
第一，线程竞争监控默认关闭。不调用 setThreadContentionMonitoringEnabled(true)，getBlockedTime() 恒为 -1；getBlockedCount() 仍会计数（本节实跑未开启该开关，日志里照样读到 blockedCount=1）。开启之后，在一个阻塞约 100 ms 的线程上读到：
while-blocked state=BLOCKED blockedCount=1 blockedTimeMs=111 owner=main
afterExit=null enabled=true
111 ms 是累计值，包含该线程历史上所有阻塞；它不能告诉你「这一次等了多久」。而且线程退出后 getThreadInfo 返回 null，采集器必须判空。用它做「本次阻塞时长」是错的，正确做法是记录第一次观察到 BLOCKED 的时间，用后续扫描的时间差估算。
第二，虚拟线程不在 getAllThreadIds() 里。本机启动一个命名为 v-1 的虚拟线程后，getAllThreadIds() 返回的 9 个 ID 中没有它。虚拟线程的阻塞诊断要走 JFR（jdk.VirtualThreadPinned 等）或 6.2 讲的办法，不要指望 ThreadMXBean。
第三，getThreadInfo 不是免费的。本机 6 个平台线程、连续 500 次调用的平均值：
cost threads=6 depth0=9346ns depth8=25997ns
不要栈约 9.3 µs，带 8 层栈约 26 µs。线程数越多越贵，因为每次都要遍历线程列表并抓栈。按 20 ms 一次扫描算，26 µs 只占单核的 0.13%，可以接受；但如果 1000 个线程、每 5 ms 扫一次、每次都抓 32 层栈，就会变成可观的固定开销，而且抓栈需要 JVM 在安全点协作。采样是必须的，不是可选的。
实测：200 ms 临界区与 8 个请求
靶子做三件事：4 个 worker 线程从一个固定池取任务；每个任务在 ThreadLocal 里放 requestId，同时写入 ConcurrentHashMap<threadId, requestId>；临界区里 sleep(200)。监控线程每 20 ms 扫一次，只处理 BLOCKED 且线程名以 loan-worker- 开头的，按 1/4 采样打印。
import java.lang.management.ManagementFactory;
import java.lang.management.ThreadInfo;
import java.lang.management.ThreadMXBean;
import java.time.Instant;
import java.util.Locale;
import java.util.concurrent.ConcurrentHashMap;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.ThreadFactory;
import java.util.concurrent.ThreadPoolExecutor;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.AtomicInteger;
import java.util.concurrent.atomic.AtomicLong;
public final class BlockingTraceProbe {
static final ThreadLocal<String> CURRENT_REQUEST = new ThreadLocal<>();
static final ConcurrentHashMap<Long, String> IN_FLIGHT = new ConcurrentHashMap<>();
static final Object DAO_LOCK = new Object();
static final AtomicLong detections = new AtomicLong();
static final AtomicLong sampled = new AtomicLong();
static final ThreadMXBean MX = ManagementFactory.getThreadMXBean();
static void begin(String requestId) {
CURRENT_REQUEST.set(requestId);
IN_FLIGHT.put(Thread.currentThread().threadId(), requestId);
}
static void end() {
IN_FLIGHT.remove(Thread.currentThread().threadId());
CURRENT_REQUEST.remove();
}
static void log(String event, String message) {
String requestId = CURRENT_REQUEST.get();
System.out.printf(Locale.ROOT,
"ts=%s level=INFO thread=%s requestId=%s event=%s msg=%s%n",
Instant.now(), Thread.currentThread().getName(),
requestId == null ? "-" : requestId, event, message);
}
public static void main(String[] args) throws Exception {
measureCost();
ThreadFactory factory = new ThreadFactory() {
private final AtomicInteger seq = new AtomicInteger();
@Override
public Thread newThread(Runnable r) {
return Thread.ofPlatform().name("loan-worker-" + seq.incrementAndGet()).unstarted(r);
}
};
ExecutorService pool = Executors.newFixedThreadPool(4, factory);
Thread monitor = Thread.ofPlatform().name("block-monitor").start(BlockingTraceProbe::monitorLoop);
long start = System.nanoTime();
for (int i = 1; i <= 8; i++) {
String requestId = String.format("REQ-%02d", i);
pool.execute(() -> handle(requestId, start));
Thread.sleep(15);
}
pool.shutdown();
pool.awaitTermination(10, TimeUnit.SECONDS);
monitor.interrupt();
monitor.join(2_000);
System.out.printf(Locale.ROOT, "summary detections=%d sampled=%d inFlightLeft=%d%n",
detections.get(), sampled.get(), IN_FLIGHT.size());
}
static void handle(String requestId, long startNanos) {
begin(requestId);
long t0 = System.nanoTime();
log("request-begin", "enter service");
log("dao-enter", "about to call repository under monitor");
synchronized (DAO_LOCK) {
try {
Thread.sleep(200);
} catch (InterruptedException e) {
Thread.currentThread().interrupt();
}
}
log("dao-exit", "repository returned");
long costMs = (System.nanoTime() - t0) / 1_000_000L;
log("request-end", "costMs=" + costMs
+ " sinceSubmitMs=" + (System.nanoTime() - startNanos) / 1_000_000L);
end();
}
static void monitorLoop() {
while (!Thread.currentThread().isInterrupted()) {
long[] ids = MX.getAllThreadIds();
ThreadInfo[] infos = MX.getThreadInfo(ids, 8);
for (ThreadInfo info : infos) {
if (info == null || info.getThreadState() != Thread.State.BLOCKED) {
continue;
}
if (!info.getThreadName().startsWith("loan-worker-")) {
continue;
}
long seq = detections.incrementAndGet();
if (seq % 4 != 0) {
continue;
}
sampled.incrementAndGet();
String requestId = IN_FLIGHT.getOrDefault(info.getThreadId(), "-");
StackTraceElement top = info.getStackTrace().length == 0
? null : info.getStackTrace()[0];
System.out.printf(Locale.ROOT,
"ts=%s level=WARN thread=block-monitor detection=%d state=%s worker=%s tid=%d "
+ "requestId=%s blockedCount=%d lock=%s owner=%s top=%s%n",
Instant.now(), seq, info.getThreadState(), info.getThreadName(),
info.getThreadId(), requestId, info.getBlockedCount(),
info.getLockName(), info.getLockOwnerName(),
top == null ? "-" : top.getClassName() + "." + top.getMethodName()
+ ":" + top.getLineNumber());
}
try {
Thread.sleep(20);
} catch (InterruptedException e) {
return;
}
}
}
static void measureCost() {
long[] ids = MX.getAllThreadIds();
long t0 = System.nanoTime();
for (int i = 0; i < 500; i++) MX.getThreadInfo(ids, 0);
long depth0 = (System.nanoTime() - t0) / 500;
t0 = System.nanoTime();
for (int i = 0; i < 500; i++) MX.getThreadInfo(ids, 8);
long depth8 = (System.nanoTime() - t0) / 500;
System.out.printf(Locale.ROOT,
"cost threads=%d depth0=%dns depth8=%dns%n", ids.length, depth0, depth8);
}
}
运行后，与本条线索相关的输出如下（节选，ts 是 Instant.now() 的 UTC 表示；源码行号随排版变化，不必对齐）：
cost threads=6 depth0=9346ns depth8=25997ns
ts=...05.228731Z level=INFO thread=loan-worker-1 requestId=REQ-01 event=dao-enter msg=about to call repository under monitor
ts=...05.249653Z level=INFO thread=loan-worker-2 requestId=REQ-02 event=dao-enter msg=about to call repository under monitor
ts=...05.272380Z level=INFO thread=loan-worker-3 requestId=REQ-03 event=dao-enter msg=about to call repository under monitor
ts=...05.295045Z level=INFO thread=loan-worker-4 requestId=REQ-04 event=dao-enter msg=about to call repository under monitor
ts=...05.302225Z level=WARN thread=block-monitor detection=4 state=BLOCKED worker=loan-worker-3 tid=28 requestId=REQ-03 blockedCount=1 lock=java.lang.Object@2fd17c20 owner=loan-worker-1 top=BlockingTraceProbe.handle:78
ts=...05.382167Z level=WARN thread=block-monitor detection=12 state=BLOCKED worker=loan-worker-2 tid=27 requestId=REQ-02 blockedCount=1 lock=java.lang.Object@2fd17c20 owner=loan-worker-1 top=BlockingTraceProbe.handle:78
ts=...05.441012Z level=INFO thread=loan-worker-1 requestId=REQ-01 event=request-end msg=costMs=212 sinceSubmitMs=218
ts=...05.723698Z level=WARN thread=block-monitor detection=48 state=BLOCKED worker=loan-worker-2 tid=27 requestId=REQ-06 blockedCount=2 lock=java.lang.Object@2fd17c20 owner=loan-worker-3 top=BlockingTraceProbe.handle:78
ts=...06.269684Z level=INFO thread=loan-worker-1 requestId=REQ-05 event=request-end msg=costMs=828 sinceSubmitMs=1049
ts=...06.875129Z level=INFO thread=loan-worker-4 requestId=REQ-08 event=request-end msg=costMs=815 sinceSubmitMs=1654
summary detections=126 sampled=31 inFlightLeft=0
这段输出能回答开头那三个问题。
等了多久。 REQ-03 在 05.272 打完 dao-enter，05.302 就被扫到 BLOCKED；REQ-01 在 05.438 才 dao-exit，临界区实测 212 ms。从 detection 计数看，监控线程在 REQ-03 的阻塞窗口内至少扫到它 4 次，可以据此估算等待时长。注意这是下界：真实开始等待的时刻在两次扫描之间，误差上限就是一个扫描周期（20 ms）。
是哪个请求。 每条 WARN 都带 requestId=REQ-03。这个字段不是 ThreadMXBean 给的，而是监控线程拿 info.getThreadId() 去 IN_FLIGHT 里查出来的。如果没有这张表，日志里只有 loan-worker-3 BLOCKED；而 loan-worker-3 在 05.850 又接了 REQ-07，线程名和请求不是一一对应。
锁被谁持有。 owner=loan-worker-1，再用同一个注册表查 26 号线程，就能把持有者归因到 REQ-01。lock=java.lang.Object@2fd17c20 在本次进程内唯一标识这把监视器；跨进程、GC 之后不能拿来比较。
还有一个值得注意的现象：临界区只有 200 ms，但 REQ-05 的 costMs=828、REQ-08 的 costMs=815。原因是 synchronized 是非公平的，刚释放的锁容易被新到达的线程抢走，排队的老请求被反复插队。这不是 ThreadMXBean 的问题，而是「200 ms 临界区 + 非公平监视器」的尾延迟放大；定位到这一点之后，修复方向是缩短临界区或换公平锁/分段锁（11.3），而不是继续加线程。
只有访问日志行不行？ 不行。在 05.30 那一刻，日志里有 4 条 request-begin 没有对应的 request-end，候选是 REQ-01 到 REQ-04 四个。要缩到一个，必须知道「哪个线程正在服务哪个请求」，而线程名在这一批里恰好还能对上，下一批就换人了。注册表就是把这个映射显式化。
埋点方案：ThreadLocal + 注册表 + 结构化日志 + 采样
把实验代码收敛成可复用的采集器，核心是四件事：
- 请求入口写上下文。
ThreadLocal供本线程日志使用，ConcurrentHashMap<threadId, requestId>供其他线程查询；退出时必须两边都清理。 - 日志字段固定。 至少包含
ts、level、thread、requestId、event、msg；有 traceId 的话一并带上，方便跳到调用链系统。 - 只在超过阈值后上报。 第一次看到 BLOCKED 只记开始时间，连续观察到同一线程仍在阻塞且超过 100 ms 才输出，避免把正常的短临界区刷屏。
- 采样与限流。 状态计数每次扫描都做（便宜），抓栈按 1/N 采样；同一
(threadId, requestId, owner)在 5 秒内只报一次。
import java.lang.management.ManagementFactory;
import java.lang.management.ThreadInfo;
import java.lang.management.ThreadMXBean;
import java.util.HashSet;
import java.util.Map;
import java.util.Set;
import java.util.concurrent.ConcurrentHashMap;
import java.util.function.LongFunction;
public final class BlockageWatch {
private final ThreadMXBean mx = ManagementFactory.getThreadMXBean();
private final LongFunction<String> requestOf;
private final long thresholdNanos;
private final long reportIntervalNanos;
private final int stackDepth;
private final Map<Long, Long> blockedSince = new ConcurrentHashMap<>();
private final Map<Long, Long> lastReported = new ConcurrentHashMap<>();
private long scans, reports;
public BlockageWatch(LongFunction<String> requestOf, long thresholdMillis,
long reportIntervalMillis, int stackDepth) {
this.requestOf = requestOf;
this.thresholdNanos = thresholdMillis * 1_000_000L;
this.reportIntervalNanos = reportIntervalMillis * 1_000_000L;
this.stackDepth = stackDepth;
}
public void scan() {
scans++;
long now = System.nanoTime();
Set<Long> stillBlocked = new HashSet<>();
for (ThreadInfo info : mx.getThreadInfo(mx.getAllThreadIds(), stackDepth)) {
if (info == null || info.getThreadState() != Thread.State.BLOCKED) {
continue;
}
long id = info.getThreadId();
stillBlocked.add(id);
long since = blockedSince.computeIfAbsent(id, ignored -> now);
long waited = now - since;
if (waited < thresholdNanos || scans % 4 != 0) {
continue;
}
Long last = lastReported.get(id);
if (last != null && now - last < reportIntervalNanos) {
continue;
}
lastReported.put(id, now);
reports++;
System.out.printf("level=WARN event=pool-blocked worker=%s requestId=%s "
+ "waitedMsAtLeast=%d owner=%s top=%s%n",
info.getThreadName(), requestOf.apply(id), waited / 1_000_000L,
info.getLockOwnerName(), topFrame(info));
}
blockedSince.keySet().retainAll(stillBlocked);
lastReported.keySet().retainAll(stillBlocked);
}
private static String topFrame(ThreadInfo info) {
StackTraceElement[] frames = info.getStackTrace();
if (frames.length == 0) {
return "-";
}
StackTraceElement top = frames[0];
return top.getClassName() + "." + top.getMethodName() + ":" + top.getLineNumber();
}
}
这段代码有两个刻意的设计。waitedMsAtLeast 的命名提醒读者它是下界；blockedSince 与 lastReported 在扫描结束时按当前阻塞集合裁剪，避免长时间运行后 map 只增不减。scans % 4 是采样，生产上可以换成按 threadId 哈希或按请求 token 采样，保证不同线程都能被轮到。
ThreadLocal 一侧仍然要 remove()。线程池复用线程时，不清理会把上一个请求的 ID 带给下一个请求，日志归因直接错位，而且 ThreadLocal 的值会跟着线程活很久。InheritableThreadLocal 也不解决问题：它只在创建子线程时复制，线程池里的线程不是请求的子线程。JDK 25 已转正的 ScopedValue 更适合结构化并发，但跨线程查询同样需要注册表，原因还是那条：别人读不到你的绑定值。
在 libraryd-conc 里落地
conc-ops 里把采集器接在 LoanService.reserve 的入口和出口：
public Reservation reserve(String isbn, String memberId) {
String requestId = RequestIds.next();
RequestContext.begin(requestId);
try {
log("request-begin", "isbn=" + isbn);
Reservation reservation = delegate.reserve(isbn, memberId);
log("request-end", "loanId=" + reservation.loanId());
return reservation;
} finally {
RequestContext.end();
}
}
监控线程持有 BlockageWatch，每 20 ms 调一次 scan()，requestOf 直接传 RequestContext::currentRequestOf（内部读 IN_FLIGHT）。告警侧不直接对「检测到 BLOCKED」报警，而是对「同一请求的阻塞下界超过 500 ms」或「每分钟阻塞请求数超过阈值」报警；前者是症状，后者才是容量信号。采样日志进本地文件，聚合计数进指标系统，两者用同一个 requestId 关联。
什么时候不要用这套：
- 虚拟线程为主的应用。
ThreadMXBean看不到虚拟线程，应该用 JFR 的虚拟线程事件；混跑时只对平台线程池开启。 - 极短临界区（微秒级）。20 ms 的扫描周期基本抓不到，收益低于开销，直接用 JFR 的阈值录制。
- 线程数上千且每个请求都要抓栈。把
stackDepth降到 4，采样比降到 1/16，否则抓栈本身就是负担。
常见错误与边界
- 从监控线程读别人的
ThreadLocal。 读到的永远是自己线程的值（通常是null），必须用注册表。 - 把
getBlockedCount()当本次阻塞时长。 它是累计次数；getBlockedTime()是累计毫秒，且默认关闭、返回 -1。 - 忘了
ThreadLocal.remove()。 线程复用时请求 ID 串台，注册表也会留下已结束请求的映射。 - 只认
BLOCKED。 等连接池、等队列、LockSupport.park都是WAITING/TIMED_WAITING，只筛BLOCKED会漏掉大部分真实阻塞。 - 不留
requestId就退出。 线程结束时注册表项不清理，既是内存泄漏，也会让后续归因指向错误的请求。 - 在虚拟线程上等
getAllThreadIds()。 它不会出现，采集器会永远报「没有阻塞」。
小结
阻塞诊断的证据链由三段拼成：ThreadMXBean 给出「谁在等、等什么锁、谁持有」，请求上下文注册表给出「这个线程正在服务哪个请求」，两次扫描的时间差给出「至少等了多久」。ThreadLocal 只解决本线程日志的归属，跨线程可见性必须靠注册表。
本机实测的三个数字：6 个平台线程、8 层栈的一次全量快照约 26 µs，所以采样不可省；200 ms 的临界区在非公平监视器下把个别请求推到 815 ms，尾延迟不是临界区长度本身；1.7 秒内检出 126 次 BLOCKED、按 1/4 采样输出 31 条，每条都能落到具体 requestId。下一节把这些证据变成阈值：什么水位该 P1，什么水位只配 P3，以及为什么「指标已经饱和但没告警」。
阅读导航：上一节 12.1 线程与池的指标口径 ｜ 下一节 12.3 告警阈值与容量水位
继续阅读
探索更多技术文章
浏览归档，发现更多关于系统设计、工具链和工程实践的内容。