CPU 只有 38% 但上下文切换从 900/s 飙到 11000/s：用 pidstat 区分「自愿 vs 非自愿」锁住锁 convoy 的完整排查

结论先行：「CPU 低 + P99 爆炸 + 上下文切换暴涨」是一个指纹，不是一个问题。这个指纹背后至少藏着三类完全不同的根因——线程过订阅、锁 convoy、分配器锁争用——它们的修复手段完全互斥（调线程数 / 改锁结构 / 换分配器），猜错方向就是白调。本文给一套用 pidstat -w 的 involuntary 占比 + perf lock 热点定位的鉴别决策树，以及一份可直接抄的监控告警配置。

一、现象：CPU 38%、GC 安静、下游正常，P99 却从 12ms 涨到 900ms

背景交代清楚：

服务：用户中心（Spring Boot 3.1.5 / JDK 17.0.11），16C64G 单实例，入口 QPS 约 1200，Web 线程池 200 线程。
事故：某晚 21:40 开始，网关侧 P99 从基线 12ms 逐步爬到 900ms，持续 40 分钟；超时率 0.02% → 4.7%。
迷惑点（这是排查最容易走歪的地方）：
- top 看 CPU 利用率只有 38%，16 核里 10 核以上基本闲着；
- G1 Young GC 平均 9ms，没有 Mixed / Full，gc.log 干净；
- 下游 MySQL、Tair 的 RT 都正常（<5ms）；
- 唯一不对劲的指标是 vmstat 1 的 cs 列从基线 ~900/s 涨到 ~11000/s，runq 长期 20+。

第一反应很容易是「线程开多了，过订阅」——这个方向本身没错，但我们先不猜，看数据。

二、原理：vmstat 的 cs 是个「合计数」，它把三种完全不同的病混在一起

vmstat 的 cs 列统计的是所有自愿 + 非自愿上下文切换的总和，这个设计本身就会误导人。拆开看内核语义：

自愿切换（voluntary）：线程自己调用 futex_wait、epoll_wait、read 等主动让出 CPU。占比高 = 应用「在等东西」，等 IO、等锁、等下游，这本身不一定有病。
非自愿切换（involuntary）：线程在 RUNNABLE 状态，但时间片用完或让位给更高优先级被调度器抢下 CPU。占比高 = 可运行的线程数超过了 CPU 能同时喂饱的数量，即「过订阅」或「大量线程在自旋抢锁」。

三类根因在这个指纹下的区别：

| 根因 | 机制 | involuntary 占比 | 特征 | |---|---|---|---| | 过订阅（线程数 >> 核数） | 每个线程时间片短，排队轮转 | 高（>70%） | 线程数/配额比 >4，jstack 里大量 TIMED_WAITING | | 锁 convoy | 一个 synchronized 上排 100+ 线程，唤醒后没跑就被抢下 | 高（>60%） | perf lock 单点热点，等锁线程数远超核数 | | 分配器锁（glibc arena） | 多线程 malloc/free 争 arena 锁 | 中等（40%~70%） | perf lock 热点在 __libc_malloc 附近 |

我们这次的根因是锁 convoy，但仅凭 cs 总量看不出来——900→11000 的暴涨，过订阅也能造出来。必须拆开。

三、具体做法：三步定位，全部命令可复现

第 1 步：pidstat 拆自愿/非自愿

# 每秒采样，-w 看自愿/非自愿切换，-t 看线程级
pidstat -w 1 10
# 关键字段：
#  cswch/s    自愿切换/秒
#  nvcswch/s  非自愿切换/秒

我们当时的输出（事故中）：

Cswch/s   Nvcswch/s  Command
  420      10580     java (pid 2318)

involuntary 占比 96%。这个比例排除了「应用等 IO」的方向（等 IO 应该是 voluntary 为主），把嫌疑集中到「可运行线程太多」——过订阅或自旋。

第 2 步：区分过订阅 vs 自旋

# 看进程实际线程数
ls /proc/2318/task | wc -l        # 输出 217（200 web + 17 系统）
# 16 核，217 线程，比值 13.5 : 1

单看 13.5:1 确实像过订阅。但过订阅的线程大多在睡（WAITING），真正在抢 CPU 的不会多。用 perf 看调度热点：

# 采样 10 秒，看锁竞争
perf lock record -p 2318 -- sleep 10
perf lock report --sort lock

输出里同一个 synchronized 地址占了 87% 的 contention 时间，反查符号是 CacheWrapper.get 里的 synchronized(this)。再对 jstack 做统计：

jstack 2318 | grep -B1 "CacheWrapper.get" | grep -c "blocked"
# 输出 183

183 个线程堵在同一把锁上——这就是锁 convoy：16 个核喂不饱 183 个排队线程，调度器不停在它们之间切换，involuntary 爆表，而真正持锁干活的线程只有一个，所以 CPU 才 38%。

第 3 步：找到「谁让所有人排队」

代码里是这样的一个经典写法：

public UserDTO get(String uid) {
    UserDTO cached = localCache.get(uid);
    if (cached != null) return cached;
    synchronized (this) {              // ← 单锁
        cached = localCache.get(uid);
        if (cached == null) {
            cached = tairGet(uid);    // 1~3ms
            localCache.put(uid, cached);
        }
    }
    return cached;
}

触发条件：21:40 一次定时任务把 localCache 整体清空（TTL 批量到期 + 主动失效），随后 400ms 内的 1200 QPS 全部穿透到这把锁上。单锁 + 批量失效 = convoy 的完美温床。

修复（两选一，我们选了 B）

A. 换 Caffeine 的 AsyncLoadingCache（自带 per-key 单飞，同 key 并发只放一个 loader，其他等结果，锁粒度从「全局一把」降到「每 key 一把」）：

Cache<String, CompletableFuture<UserDTO>> cache = Caffeine.newBuilder()
    .expireAfterWrite(5, TimeUnit.MINUTES)
    .buildAsync();

public UserDTO get(String uid) {
    return cache.get(uid, k -> CompletableFuture.supplyAsync(() -> tairGet(k)))
                .join();   // 同 key 并发自动合并为一次 tairGet
}

B. 消灭批量失效：把「定时全量清空」改成「逐 key 随机 TTL 抖动」（baseTtl + rand(0, 30%)），让失效时刻分散，单锁瞬间排队数从 183 降到个位数。我们两个都做了，压测（JMeter 1500 并发）验证：P99 回到 14ms，cs 回到 ~950/s，involuntary 占比 96% → 31%。

四、踩过的坑与反直觉之处

vmstat 的 cs 是全局值，且早期内核只统计本地 CPU 上的切换——多核机器上它系统性低估真实切换量。看趋势可以，看绝对值会骗人。要进程级、可加总的数，用 pidstat -w 或读 /proc/<pid>/status 的 voluntary_ctxt_switches / nonvoluntary_ctxt_switches 两次采样做差。
involuntary 高 ≠ 一定过订阅。过订阅的线程大多在睡，真正制造 involuntary 的是「可运行但排不上」的那一小撮——自旋抢锁的线程才是主犯。所以第 2 步的 perf lock 不能跳。
锁 convoy 的 CPU 曲线有特征：持锁线程所在核 CPU 接近 100%，其余核 20%~40%。如果 16 核里只有 1~2 核打满、整体 38%，这个形状本身就是 convoy 的侧写，比看 cs 更快。
synchronized 在 JDK 6+ 有偏向锁/轻量级锁自旋优化，但 convoy 场景下自旋会放大 CPU 浪费——183 个线程各自旋几百 ns，加起来比持锁线程真正干活的 1ms 还多。锁排队越长，自旋越亏。
告警别配绝对值。cs 的绝对量跟线程数、核数强相关，换规格就失效。应该告警「involuntary / (voluntary + involuntary) 占比 > 60% 且持续 3 分钟」+「cs/s 相对 7 天基线突增 5 倍以上」，双条件联动才不误报。

五、结论与可复用清单

核心结论：「CPU 低 + P99 高 + cs 暴涨」是指纹，不是根因。鉴别路径：

cs 暴涨
 ├─ pidstat -w：voluntary 为主（>70%）
 │    └─ 应用在等 → 查 IO（iostat）、下游 RT、连接池 wait
 └─ involuntary 为主（>70%）
      ├─ 线程数/核数 > 4 且 jstack 大量 WAITING
      │    └─ 过订阅 → 调线程数 / 检查 ForkJoinPool 默认并行度
      ├─ perf lock 单点热点 + jstack 大量 BLOCKED
      │    └─ 锁 convoy → 改锁粒度（per-key / striping）/ 消灭批量失效
      └─ perf lock 热点在 malloc/free
           └─ 分配器争用 → MALLOC_ARENA_MAX=2 或换 tcmalloc

可复用清单（可直接进 runbook）：

告警：nonvoluntary_ctxt_switches 5 分钟增量 > 7 天同窗口基线 ×5，且 involuntary 占比 >60%；
定位三板斧：pidstat -w 1 → ls /proc/<pid>/task | wc -l → perf lock record；
代码侧自查：搜 synchronized (this) + cache.clear() / invalidateAll() 组合，这是 convoy 温床的高发写法；
修复优先级：消灭「批量失效」> 换 per-key 锁 > 加锁粒度 > 加线程数（加线程数对 convoy 无效甚至加重）。

留一个开放问题给各位：锁 convoy 和「过订阅」的修复手段互斥，但它们的监控指纹高度相似——你们线上有没有遇到过「按过订阅修了、cs 降了一半但 P99 没回来」的情况？如果是，多半是 convoy 里还混着另一层锁。欢迎在评论区贴你的 pidstat 输出，一起拆。

0赞 0收藏 0评论 1浏览