线程池的排队时间：一个被「active 线程数」掩盖的 P99 盲区

结论先行：你监控的永远是线程池「在干活的时间」，而不是任务「等干活的时间」。ThreadPoolExecutor 的 active/queueSize 指标全绿，不代表 P99 健康——只要队列在涨，任务从 submit() 到真正被 worker 执行的这段「排队时间」就会悄悄吃掉你的 P99，而这段延迟在 CPU、GC、下游 RT 的任何一块监控上都是隐形的。下面是一次真实排障 + 一套可直接复用的埋点方案。

一、现象：所有面板都绿，只有 P99 在尖叫

服务：营销权益发放服务（Spring Boot 3.2.4 / JDK 17.0.9 / G1），4 实例，单实例 8C16G，入口 QPS 约 600。
链路：HTTP 线程 → 业务线程池 coupon-pool（corePoolSize=32, maximumPoolSize=64, ArrayBlockingQueue(256)）→ 调下游「规则引擎」（正常 P50 ≈ 12ms）。
事故时间窗（11:02–11:09）：入口 P99 从基线 82ms 一路爬到 3.2s，超时率 0.1% → 7.8%。
诡异点（排查时的「全绿」）：
- coupon-pool active 线程数峰值 33/64，看着「还有富余」；
- CPU 使用率 46%，无 Full GC（Young GC 平均 6ms）；
- 下游规则引擎自己监控的 P99 只有 145ms——「下游也没慢」；
- 没有线程 BLOCKED 堆栈，没有死锁。

四个面板全部指向「系统很健康」，只有入口 P99 在尖叫。这就是本文的核心问题：延迟去哪了？

二、根因：延迟藏在「submit → 真正执行」的缝里

先把机制讲清楚，否则后面都是玄学：

ThreadPoolExecutor 的执行模型是 先填 core、再填队列、最后扩 max。这意味着只要 core=32 没打满，新增任务不会创建新线程，而是全部进队列排队。所以「active=33/64 看起来很闲」恰恰是危险信号——它说明第 33 个并发任务出现后，后续所有任务都在排队，而不是并行。
事故根因本身并不神秘：11:02 规则引擎侧一次慢 SQL 使其 P50 从 12ms 涨到 180ms（持续约 7 分钟）。单任务执行时间 ×15，32 个 worker 的吞吐从 ~2600 任务/s 掉到 ~180 任务/s，队列开始堆积。
关键账（用 Little's Law 算）：队列 256 个积压任务 ÷ 180 任务/s ≈ 1.4s 排队时间。这就是 P99 从 82ms → 3.2s 里多出来的那 ~2.5s（1.4s 排队 + 145ms 下游 + 抖动）。
为什么监控看不到？ 因为我们的耗时埋点写在了 task 内部：long t0 = now(); doWork(); record(now() - t0)。这段 now() - t0 只覆盖「执行」，不覆盖「排队」。而 queueSize 指标我们只配了告警阈值 200——事故时队列峰值 253，告警响了但被当普通抖动忽略了，因为没有任何人把「queueSize=253」翻译成「≈1.4s 用户延迟」。

一句话总结：排队时间是「队列深度 × 任务均值耗时 ÷ 有效吞吐」的函数，任何只看「执行耗时」或只看「线程数」的监控，对这段延迟都是盲的。

三、具体做法：把排队时间变成一等公民指标

1. 最小侵入埋点（不改业务代码，包一层）

// 用装饰器包住所有提交入口，统一记录 submit→run 的间隔
public class QueueWaitTracingExecutor extends ThreadPoolExecutor {
    private final MeterRegistry registry;

    public QueueWaitTracingExecutor(int core, int max, int qsize, MeterRegistry registry) {
        super(core, max, 60, TimeUnit.SECONDS,
              new ArrayBlockingQueue<>(qsize),
              new ThreadFactoryBuilder().setNameFormat("coupon-pool-%d").build(),
              new AbortPolicy()); // 见第五节：拒绝要大声
        this.registry = registry;
    }

    @Override
    public <T> Future<T> submit(Callable<T> task) {
        long submitAt = System.nanoTime();
        return super.submit(() -> {
            long waitMs = (System.nanoTime() - submitAt) / 1_000_000;
            registry.timer("pool.queue.wait", "pool", "coupon-pool")
                    .record(waitMs, TimeUnit.MILLISECONDS);
            return task.call();
        });
    }
}

要点：计时起点必须在提交线程的 submit() 里取，终点在 worker 线程执行第一行时取——这样才能把「跨线程的排队」完整框住。Gauge 类指标（queue.size、active.count）保留，但告警必须改成对 pool.queue.wait 的 P99 告警（我们设的阈值：P99 > 200ms 持续 1 分钟）。

2. 容量公式：队列深度该多大，用 Little's Law 反推

别再拍脑袋写 256/1024。公式：

可接受排队时间 W  =  SLO_P99 - 期望执行时间
队列上限 Q  ≈  W × 期望吞吐（任务/s）

例：SLO P99 = 300ms，正常执行 100ms → 允许排队 200ms；正常吞吐 ~2600 任务/s，则 Q ≈ 200ms × 2600 ≈ 500。再考虑下游劣化 5 倍的退化场景，吞吐掉到 ~500 任务/s，Q=500 意味着排队 1s——超过 SLO，所以正确动作不是加大队列，而是「快失败 + 降级」（见下）。

3. 拒绝要大声，降级要有默认值

AbortPolicy 拒绝时抛 RejectedExecutionException，在网关侧统一转 429 + Retry-After（而不是 500），并打 pool.rejected.count 计数指标——拒绝是好信号，它把排队延迟截断在了用户可感知之前；
为每个可降级子任务准备默认值/空集合返回，超时用 orTimeout(200ms) 包住 future.get()——注意 orTimeout 超时后任务仍在跑，它只释放等待者，不回收线程，别把它当熔断用。

四、踩过的坑（都是反直觉的）

「把队列从 256 加到 1024」让 P99 更差，不是更好。 我们灰度试过：队列加大后积压从 253 涨到 900+，排队时间从 ~1.4s 涨到 ~5s，P99 从 3.2s 涨到 6s+。队列是延迟的蓄水池，不是缓冲垫——它把「拒绝」推迟了，把「慢」放大了。
CompletableFuture.supplyAsync(supplier, pool) 会吞掉排队时间。 如果下游用 future.get(timeout) 取结果，超时窗口是从 get() 开始的，但任务可能还在队列里没开始跑——你会看到大量「get 超时」却以为「执行太慢」。埋点必须打在 task 体内第一行，而不是调用侧。
active 线程数低 ≠ 池子健康。 本例 active 峰值只有 33/64。正确读法是：active 打满 core + queue 在涨 才是「池子已经饱和」的标准姿势——因为 maximumPoolSize 只有在队列满之后才会用到，很多池子 max 参数从头到尾是个摆设。
queueSize 告警没有「翻译层」没人听。 253 这个数字本身不可怕，可怕的是没有人把它换算成「≈1.4s 用户延迟」。告警文案里直接带上换算后的时间，值班响应速度完全不一样。

五、结论与可复用清单

[ ] 给每个业务线程池加 pool.queue.wait 计时指标（submit→run 第一行），对 P99 告警；
[ ] 队列容量用 W × 吞吐 反推，而不是抄 256/1024；
[ ] 拒绝策略选 Abort + 网关转 429，让「快失败」替代「慢慢排」；
[ ] 排查 P99 抖动时，第一个要问的问题从「下游慢吗」改成「任务是排队进来的，还是直接开跑的」；
[ ] 记住 Little's Law：排队时间 ≈ 队列深度 ÷ 当前吞吐，出事故时 30 秒能心算出延迟去了哪。

排队延迟和 CPU、GC、下游 RT 是并列的第四大延迟来源，却最常被漏监控——因为它发生在「两个线程的交接缝」里，任何只看单侧的指标都照不到它。

0赞 0收藏 0评论 2浏览

P99 从 80ms 飙到 3.2s 而 CPU、active 线程、下游全绿：线程池「排队时间」监控盲区的一次实战与埋点方案