接口“偶发”卡 3 秒？它其实很准时：一次 Full GC 频繁的追凶记

“杰哥，我们的商品详情接口最近老是偶发变慢，一般 20 毫秒，偶尔冲到 3 秒，刷新一下又好了。是不是网络？”测试同学发来消息，还附了一张监控截图：P99 曲线像心电图，隔一阵就来一个尖峰。

我看着那张图，第一反应是“偶发”这两个字用得不严谨——真正的偶发是没有规律的，而这张图的尖峰间隔大致相同，甚至越来越密。有规律的“偶发”，多半是一个周期性的、后台的东西在捣乱。JVM 里最爱周期性捣乱的，就是垃圾回收。

这篇记下这次排查：怎么证明“卡顿 = GC”，GC 日志在 JDK8 与 JDK11+ 上分别怎么开，jstat -gcutil 怎么看趋势，这次的凶手（无界缓存）怎么揪出来，以及 G1 与 CMS 到底怎么选。

一、现象：CPU 不高，但延迟尖峰很准时

先看几个基础事实，把“网络抖动”这个背锅侠排除掉：

尖峰同时出现在同一个实例的所有接口上，不只是商品详情——网络问题不会这么“雨露均沾”；
调用链里每个下游的耗时都正常，多出来的 3 秒不在任何远程调用里，而是整个进程停了一下；
业务日志里，同一秒内的所有请求日志突然集体断档，然后同时补上。这是 Stop-The-World（STW）最典型的痕迹：应用线程被集体暂停，日志线程也暂停了。

一个简单的验证方法：用 jstat 每秒采样，在尖峰发生的时候看 FGC 计数有没有跳。

$ jstat -gcutil 6120 1000
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT
  0.00  41.20  55.31  71.02  96.44  92.10   2208   31.442     14    31.870   63.312
  0.00  41.20  77.89  71.02  96.44  92.10   2208   31.442     14    31.870   63.312
 38.55   0.00   9.12  72.30  96.44  92.10   2209   31.455     14    31.870   63.325
 38.55   0.00  30.71  72.30  96.44  92.10   2209   31.455     14    31.870   63.325
  0.00   0.00  12.40  38.77  96.44  92.10   2209   31.455     15    34.902   66.357
  0.00   0.00  20.13  38.77  96.44  92.10   2209   31.455     15    34.902   66.357

倒数第二行是关键：FGC 从 14 变成 15，FGCT 从 31.870 变成 34.902——一次 Full GC 花了约 3.03 秒，恰好对上接口的 3 秒尖峰。同时老年代 O 从 72.30% 掉到 38.77%（说明这次回收回收了一些），但注意，回收之后它又会重新涨回去。

各列含义（来自 JDK 官方 jstat 文档）：S0/S1/E/O 分别是两个 Survivor、Eden、老年代的使用率；M 是 Metaspace；CCS 是压缩类空间；YGC/YGCT 是 Young GC 次数和累计秒数；FGC/FGCT 是 Full GC 次数和累计秒数；GCT 是总 GC 时间。看 GC 问题，就盯 FGC 的增量和 FGCT 的增量，再除一下，得到“每次 Full GC 多久”。

二、排查路线图

核心思想：jstat 只能告诉你“有没有 Full GC、多久一次、多久一次花多少”，不能告诉你“为什么”。“为什么”要靠 GC 日志里的 Cause 和堆里的对象分布来回答。

三、动手：开 GC 日志，看趋势，找对象

第 1 步：开 GC 日志（这一步应该是默认配置）

GC 日志的开销极小，生产环境请永远打开。JDK 9 引入了统一日志框架（-Xlog），旧的 -XX:+PrintGCDetails 系列参数在新版本里被废弃，两种写法必须分清：

# ===== JDK 8 =====
java -Xms4g -Xmx4g \
     -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps \
     -XX:+PrintGCApplicationStoppedTime \
     -Xloggc:/data/logs/gc.log \
     -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=100M \
     -jar goods-service.jar

# ===== JDK 11 / 17 =====
java -Xms4g -Xmx4g \
     -Xlog:gc*:file=/data/logs/gc.log:time,uptime:filecount=5,filesize=100m \
     -jar goods-service.jar

JDK 11+ 的写法出自官方 java 命令文档：-Xlog:gc*:file=<path>:time,uptime:filecount=<n>,filesize=<size>，其中 gc* 表示所有 GC 相关标签，time,uptime 是装饰器（墙钟时间与进程运行时间），filecount,filesize 是轮转。-XX:+PrintGCApplicationStoppedTime（JDK8）可以额外打印“应用线程实际被暂停了多久”，比 GC 时间更接近用户感受；在 JDK9+ 里对应的是 safepoint 标签，-Xlog:gc*,safepoint。

这次线上是 JDK 8 + CMS，我们抓到的日志长这样（截断）：

2026-09-24T15:02:11.804+0800: 8123.456: [GC (Allocation Failure) 8123.456: [ParNew: 1747626K->98304K(1922432K), 0.0821133 secs] 3611822K->1966501K(4019584K), 0.0824012 secs] [Times: user=0.31 sys=0.00, real=0.08 secs]
2026-09-24T15:02:14.212+0800: 8125.864: [GC (CMS Initial Mark) [1 CMS-initial-mark: 3211004K(4019584K)] 3390221K(4019584K), 0.0181177 secs]
2026-09-24T15:02:14.230+0800: 8125.882: [CMS-concurrent-mark-start]
2026-09-24T15:02:15.901+0800: 8127.553: [CMS-concurrent-mark: 1.512/1.671 secs]
2026-09-24T15:02:16.910+0800: 8128.562: [GC (Allocation Failure) 8128.562: [ParNew (promotion failed): 1747626K->1922432K(1922432K), 0.2144517 secs]
    8128.777: [CMS8129.410: [CMS-concurrent-sweep: 0.690/0.812 secs]
 (concurrent mode failure): 3801452K->2980112K(4019584K), 2.7830621 secs] 3860420K->2980112K(5942016K), [Metaspace: 89310K->89310K(1130496K)], 2.9987311 secs] [Times: user=3.01 sys=0.02, real=3.00 secs]

关键信息在最后几行：ParNew (promotion failed)——年轻代要把存活对象晋升到老年代，但老年代放不下；紧接着 CMS (concurrent mode failure)——CMS 的并发回收没有赶上分配速度，JVM 只好退化成单线程的 Serial Old 全堆标记整理，STW 了 3.00 秒（real=3.00 secs）。这跟 jstat 观察到的 3 秒吻合。

顺便，对照一下同一件事在 JDK 17 + G1 下的日志形态（统一日志格式，更易读）：

[2026-09-24T15:02:11.804+0800][8123.456s][info][gc] GC(412) Pause Young (Normal) (G1 Evacuation Pause) 1720M->1210M(4096M) 18.402ms
[2026-09-24T15:02:14.212+0800][8125.864s][info][gc] GC(413) Pause Young (Concurrent Start) (G1 Humongous Allocation) 2610M->2380M(4096M) 21.310ms
[2026-09-24T15:02:14.233+0800][8125.885s][info][gc] GC(414) Concurrent Mark Cycle
[2026-09-24T15:02:16.910+0800][8128.562s][info][gc] GC(415) Pause Full (G1 Evacuation Pause) 3980M->2960M(4096M) 2794.115ms

读 G1 日志的口诀：Pause Young 是正常回收，几十毫秒可以接受；Concurrent Mark Cycle 是并发标记；出现 Pause Full 就是坏消息，括号里的原因（Allocation Failure、Evacuation Failure、Humongous Allocation 等）就是线索。

第 2 步：GC 后老年代降不下去，是最重要的判据

从上面两份日志都能读出同一个事实：Full GC 之后老年代仍有约 2.9 GB（占 4GB 堆的 73%）。健康的应用，Full GC 之后老年代应该降到一个较低的基线（比如 20%–40%）。如果基线在缓慢爬升——比如每天爬 5%——那就是内存泄漏或者无界缓存，光调参数没用。

把 jstat 长期采样下来（或用监控看老年代“GC 后使用量”曲线），我们看到基线是一条向上的斜线：

时间       Full GC 后老年代使用量
Mon 10:00   1.1 GB
Mon 22:00   1.5 GB
Tue 10:00   1.9 GB
Tue 22:00   2.4 GB
Wed 10:00   2.9 GB   ← 开始每几分钟 Full GC 一次

这条斜线就是“泄漏画像”：每次 GC 后剩下的越来越多，Full GC 越来越频繁，卡顿越来越密。这也解释了为什么上线初期没事——问题是随时间增长的。

第 3 步：看老年代里到底是什么

线上不想 dump（3GB 的 dump 会 STW 几十秒），先用轻量的 jmap -histo 看类实例分布：

$ jmap -histo:live 6120 | head -12
 num     #instances         #bytes  class name
----------------------------------------------
   1:       8123441     1104880136  [C
   2:       8110236      194645664  java.lang.String
   3:       2890112      184967168  com.demo.goods.dto.GoodsDetailVO
   4:       2890112      138725376  java.util.HashMap$Node
   5:        410221       98453040  [B
   6:       1120334       26888016  java.util.concurrent.ConcurrentHashMap$Node
...

注意 jmap -histo:live 会先触发一次 Full GC（这也是它叫 “live” 的原因），线上慎用，最好先摘流量。结果里 GoodsDetailVO 有 289 万个实例——但商品总共才 30 多万个。实例数远超业务实体数，是缓存里存了太多份的强信号。（这里的 [C 是 char 数组，JDK8 String 的底层；JDK9+ 会变成 [B。）

接下来抓一份 heap dump（摘流量后执行 jcmd 6120 GC.heap_dump /data/dumps/goods.hprof），在 MAT 里看 Dominator Tree，第一名是：

com.demo.goods.cache.LocalCache @ 0x6c0a00120 | retained 2.31 GB
 +- static field: CACHE  java.util.concurrent.ConcurrentHashMap  (size = 2,890,112)

凶手是一个 static 的 ConcurrentHashMap，里面有 289 万条。

四、根因：一个“无界”的本地缓存

public class LocalCache {
    // 缓存商品详情，避免每次查 Redis / MySQL
    private static final Map<String, GoodsDetailVO> CACHE = new ConcurrentHashMap<>();

    public static GoodsDetailVO get(String key, Supplier<GoodsDetailVO> loader) {
        return CACHE.computeIfAbsent(key, k -> loader.get());
    }
}
// 调用方：key = goodsId + ":" + skuId + ":" + userLevel + ":" + channel + ":" + lang
GoodsDetailVO vo = LocalCache.get(buildKey(goodsId, skuId, level, channel, lang), () -> load(...));

两个设计缺陷叠加：

没有容量上限，也没有过期：只增不减的 Map，就是“慢速内存泄漏”，本质上和 static List 没有区别；
key 的组合爆炸：商品 × SKU × 用户等级 × 渠道 × 语言，30 万商品被放大成近 300 万条，而且每份 VO 里都各自带着完整的描述文本（几 KB），于是这个 Map 不断涨。

再来看为什么变成“Full GC 3 秒”而不是“Young GC 几十毫秒”。分代 GC 的基本逻辑是：短命对象在年轻代死掉，长寿对象晋升到老年代。缓存里的对象天然长寿，全都会晋升老年代，把老年代填满；而 CMS 在老年代使用率到达阈值（JDK8 默认约 92%，-XX:CMSInitiatingOccupancyFraction 可设）时才开始并发回收，且 CMS 不做整理，碎片越积越多。当一个 Young GC 需要晋升的对象放不进碎片化的老年代（promotion failed），或者并发回收的速度追不上分配速度（concurrent mode failure），CMS 就会退化为 Serial Old——单线程，全堆标记 + 整理，3GB 存活对象耗时 3 秒不奇怪。

下面这张图是这个恶性循环的时序：

五、止血与修复

止血

滚动重启：重启会清掉缓存，基线回到 1GB，可以再撑十几个小时。我们先靠这个稳住，一次重启一个实例，间隔到前一个实例预热完成；
临时调大堆或缩短缓存 key 范围：在不改代码的情况下，把 -Xmx 从 4g 加到 6g 只是延寿，要明确标注成“临时”，并同步排期根治；
先别乱开 -XX:+DisableExplicitGC 之类的“偏方”：先用 GC 日志确认 Cause，再决定要不要动它。

根治 1：缓存必须有界、有过期

把手写的 static ConcurrentHashMap 换成 Caffeine（Spring Boot 项目直接引入即可），并且把 key 收敛：与用户等级/渠道无关的商品基础信息，只按 goodsId 缓存，差异部分在返回前组装：

private static final Cache<Long, GoodsBaseVO> CACHE = Caffeine.newBuilder()
        .maximumSize(50_000)                    // 容量上限：按“条数”兜底，一定要有
        .expireAfterWrite(10, TimeUnit.MINUTES) // 过期：防止脏数据 + 让对象有机会被回收
        .recordStats()                          // 暴露命中率，方便监控
        .build();

public GoodsBaseVO get(Long goodsId) {
    return CACHE.get(goodsId, this::loadFromDb);
}

如果单个对象体积差异大，可以用 maximumWeight + weigher 按大小限制。同时把 recordStats() 的命中率、estimatedSize() 接到监控上，缓存本身就是要监控的“资源”。

根治 2：GC 选型与参数，G1 还是 CMS？

缓存修好之后，我们顺便重新评估了收集器。结论表：

维度	CMS（JDK 8 常见）	G1（JDK 9+ 默认）
状态	JDK 9 起被标记为废弃，JDK 14 已移除（JEP 363），升级 JDK 后想用也用不了	官方主推，JDK 8u 也可 `-XX:+UseG1GC`
碎片	并发标记清除，不整理，长期运行碎片积累 → promotion failed	按 Region 复制/整理，碎片可控
停顿控制	无明确目标，Full GC 时退化为单线程 Serial Old，很长	目标 `-XX:MaxGCPauseMillis`，官方默认 200ms（尽力而为，非保证）
大对象	直接进老年代	≥ Region 一半的对象是 Humongous，连续 Region 分配，可能触发提前回收；可用 `-XX:G1HeapRegionSize` 调整
调参负担	CMSInitiatingOccupancyFraction 等要手调	IHOP 默认 45% 且自适应（Adaptive IHOP）

我们的选择是：升级到 JDK 17，用 G1，几个参数如下（其余保持默认——别在没有数据的情况下堆一堆调优参数）：

java -Xms4g -Xmx4g \
     -XX:+UseG1GC \
     -XX:MaxGCPauseMillis=200 \
     -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/dumps/ \
     -XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=512m \
     -Xlog:gc*:file=/data/logs/gc.log:time,uptime:filecount=5,filesize=100m \
     -jar goods-service.jar
# 若必须留在 JDK 8 + CMS，至少加上：
#   -XX:+UseConcMarkSweepGC -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSInitiatingOccupancyFraction=70
#   -XX:+CMSParallelRemarkEnabled -XX:+CMSScavengeBeforeRemark（按需）

关于元空间：JDK 8 起永久代被移除，类元数据放在本地内存（Metaspace）。官方文档说明 默认不设上限，类元数据达到高水位（初始由 MetaspaceSize 决定，平台相关，大约 20MB 左右）就会触发一次 GC 去卸载类。所以如果日志里出现 Full GC (Metadata GC Threshold) 且频繁，说明元空间被反复顶到水位，可以把 -XX:MetaspaceSize 设大一些；同时设置 -XX:MaxMetaspaceSize 避免动态类生成（比如某些代理、脚本引擎）把本地内存吃光。

验证

改造上线后，观察 3 天：G1 日志里没有再出现 Pause Full，Young GC 平均 20 毫秒，老年代 GC 后基线稳定在 1.2GB 左右（不再爬升），P99 从 3 秒回到 60 毫秒。

六、复盘：这类坑怎么提前躲开

做法	为什么
所有生产 JVM 默认开 GC 日志（JDK8 用 PrintGCDetails 系列，JDK11+ 用 `-Xlog:gc*`），并做轮转	GC 日志开销极小；没有日志，卡顿只能靠猜
“偶发”问题先看规律：间隔是否均匀、是否所有接口同时卡	均匀且全局，多半是 GC / 定时任务 / 连接池，而不是网络
监控“Full GC 后老年代使用量”的基线，而不是只看瞬时使用率	基线爬升是泄漏最早、最准的信号
本地缓存必须设 `maximumSize` 与过期时间，并暴露命中率/大小指标	无界缓存就是泄漏；命中率低的缓存还不如不缓存
缓存 key 设计要收敛，别把与数据无关的维度拼进 key	维度笛卡尔积会让缓存条数放大成百上千倍
能升级就升级到 G1（JDK 17 起还有 ZGC 可选），别死守 CMS	CMS 已在 JDK 14 移除，且碎片问题无法根治
Full GC 次数与单次耗时接入告警（如 5 分钟内 Full GC > 2 次，或单次 > 1 秒）	让告警比用户投诉先到

一句话备忘：延迟尖峰有规律 → jstat -gcutil 盯 FGC/FGCT 增量 → GC 日志读 Cause → Full GC 后老年代降不下去就是有对象不放手（jmap -histo + MAT）→ 缓存必须有界；顺手把 CMS 换成 G1。

那天复盘会上，测试同学问我：“所以以后‘偶发’可以少报一点吗？”我说：“可以，你先把‘偶发’的时间点截图发我，凡是‘每隔十分钟准时偶发’的，我们就叫它——定时发。”

参考资料

Oracle JDK 17 GC Tuning Guide：Garbage-First (G1) 收集器——G1 默认 200ms 暂停目标、Humongous 对象定义、触发 Full GC 的场景、IHOP 默认 45% 与自适应机制。
Oracle JDK 17 java 命令手册——统一日志 -Xlog 语法（选择器、输出、装饰器、轮转选项）以及旧 GC 日志参数到 Xlog 的转换。
Oracle JDK 17 jstat 手册——-gcutil 各列含义与 interval/count 用法。
JEP 363：Remove the Concurrent Mark Sweep (CMS) Garbage Collector——CMS 在 JDK 14 被移除及其原因（此前 JEP 291 已废弃）。
Oracle JDK 8 GC Tuning：Other Considerations——永久代移除、Metaspace 默认无上限、MetaspaceSize 高水位触发 GC、MaxMetaspaceSize 与压缩类空间。

接口“偶发”卡 3 秒？它其实很准时：一次 Full GC 频繁的追凶记

一、现象：CPU 不高，但延迟尖峰很准时

二、排查路线图

三、动手：开 GC 日志，看趋势，找对象

第 1 步：开 GC 日志（这一步应该是默认配置）

第 2 步：GC 后老年代降不下去，是最重要的判据

第 3 步：看老年代里到底是什么

四、根因：一个“无界”的本地缓存

五、止血与修复

止血

根治 1：缓存必须有界、有过期

根治 2：GC 选型与参数，G1 还是 CMS？

验证

六、复盘：这类坑怎么提前躲开

参考资料

有想法，也想把它做出来？

一起聊聊

搜索文章

阅读设置

稍后阅读

一、现象：CPU 不高，但延迟尖峰很准时

二、排查路线图

三、动手：开 GC 日志，看趋势，找对象

第 1 步：开 GC 日志（这一步应该是默认配置）

第 2 步：GC 后老年代降不下去，是最重要的判据

第 3 步：看老年代里到底是什么

四、根因：一个“无界”的本地缓存

五、止血与修复

止血

根治 1：缓存必须有界、有过期

根治 2：GC 选型与参数，G1 还是 CMS？

验证

六、复盘：这类坑怎么提前躲开

参考资料

有想法，也想把它做出来？

继续探索这个话题

一起聊聊