JVM 内存与 GC：一次线上 Full GC 排查记录

系列目录

从 Node.js、C# 转到 Java 项目时，我已知道线程、连接和缓存都会受资源上限约束，也预判 JVM 的堆、分代回收和停顿会成为服务运行中的问题。因此在项目上线前先补了 HotSpot 内存分代、CMS 和 JDK 工具的基础知识，准备将它们用于监控和排障。后来服务出现周期性卡顿，这些准备并未直接给出根因，但让我能按监控、GC 日志、jstat 和 jmap 的顺序缩小范围。本文记录这次验证过程，以及其中仍不清楚的部分。

问题现场：RT 尖刺与排查范围

七月底开始，云盘主服务的 RT 监控出现规律异常：大约每小时整点过后几分钟，P99 从平时的几十毫秒升到秒级，持续十几秒后回落。期间没有发版，流量曲线平稳。

我先检查网络和下游。当时正在做 IM 融合，链路新增了下游调用；第 5 篇中下游抖动影响聚合接口的经验，也使我优先检查外部依赖。随后检查下游服务监控、数据库慢查询和机房链路，均未发现新增异常，花了大半天。这个结果要求重新回到多机同时出现和整点触发两个现象。

复盘监控时，有一条线索被忽略了：尖刺在多台机器同时出现，幅度接近，周期精确到整点。下游故障也可能同时影响多台机器，但这种规律更需要检查进程内的定时任务和 GC。GC 的 Stop-The-World（STW）阶段会暂停应用线程，因此可能同时阻塞该进程的请求处理。

回看 GC 日志后，Full GC 的时间戳与监控尖刺一一对应。上线时已开启 -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc，日志可以直接用于比对。这个证据将后续排查范围收敛到 GC。

先补齐前提：分代内存与两种 GC

开始读 GC 日志前，我先按线上 JDK 7 的实现补齐内存区域和收集器行为。JDK 8 才将永久代替换为元空间，以下内容以 JDK 7 为准。

HotSpot 的堆按分代组织，永久代则属于非堆内存：

新生代：多数新对象在这里分配。新生代包括 Eden 区和两个 Survivor 区（S0/S1）。对象先在 Eden 分配；Eden 满时触发 Young GC，存活对象会复制到 Survivor 区；对象在 Survivor 区经历多次回收后，或因 Survivor 空间和动态年龄阈值等条件而提前进入老年代。请求中的临时对象通常会在方法返回后失去引用，因此 ParNew 对新生代采用复制算法，停顿往往较短，但具体时长仍取决于存活对象、堆配置和运行环境。
老年代：保存经历多次 Young GC 后仍存活的对象。对象也可能因分配担保、对象年龄或 -XX:PretenureSizeThreshold 等配置进入老年代；PretenureSizeThreshold 的适用对象不只包括数组，是否直接分配还取决于收集器和 JVM 配置。使用 CMS 时，老年代回收的大部分工作与应用线程并发执行，初始标记和重新标记阶段仍会 STW。
永久代：保存类元数据、常量池等。它可能因类加载或动态生成类而出现 OOM，但本次日志没有显示永久代异常，因此不在本次排查范围内。

下面两类 GC 的含义不同：

Young GC（ParNew）：会 STW，但主要处理新生代。存活对象较少时，停顿通常在毫秒级。Young GC 频繁可能表示对象分配速率较高或新生代较小，也需要结合停顿时间、晋升量和吞吐量判断。
Full GC：本文观察到的 Full GC 由 CMS 的 concurrent mode failure 引发。当 CMS 在并发周期结束前无法为老年代保留足够空间时，会退化为一次 STW 的 Full GC。常见原因包括老年代增长过快、CMS 启动过晚、晋升压力过大或可用连续空间不足。停顿时长受存活对象量、堆大小和碎片等因素影响；应用线程暂停会反映为请求延迟上升。

本例中，周期性 RT 尖刺与 Full GC 时间对应，说明需要检查是否有定时任务或对象分配模式持续推高老年代占用。仅凭周期性尖刺本身，不能直接确定晋升是唯一原因。

用 GC 日志确认回收类型

GC 日志是此前学习后在项目中首先使用的证据。先用日志判断回收类型。一条 Young GC 日志如下（脱敏示意，JDK 7 + ParNew/CMS，开启了 PrintGCDateStamps 和 PrintGCDetails）：

2016-08-05T10:14:23.217+0800: 83231.445: [GC2016-08-05T10:14:23.217+0800: 83231.445: [ParNew: 884736K->73728K(983040K), 0.0871234 secs] 2123564K->1316556K(4128768K), 0.0876123 secs] [Times: user=0.31 sys=0.02, real=0.09 secs]

逐段看：

2016-08-05T10:14:23.217+0800：事件发生时间，可与监控尖刺比对；后面的 83231.445 是 JVM 启动以来的秒数。
[ParNew: 884736K->73728K(983040K), 0.087 secs]：新生代回收前 864M，回收后 72M，新生代总容量 960M，本次停顿 0.087 秒。新生代回收后占用较低，说明本次回收清除了较多新生代对象。
2123564K->1316556K(4128768K)：整个 Java 堆回收前后的已用量与总容量，分别为约 2G、约 1.25G 和 4G。将堆与新生代的变化结合，可以估计老年代的增减；在存在 CMS 并发活动时，不能将两者差值机械地等同于晋升量。
[Times: user / sys / real]：real 是该 GC 事件的墙钟耗时。user 是进程在用户态累计消耗的 CPU 时间，可能大于 real，例如多个 GC 线程并行运行。real 明显偏长时，应结合 safepoint、CPU 调度和操作系统状态继续分析，不能只据此判断为 IO 或 swap 问题。

再看 Full GC 日志（真实日志还带有 CMS 各阶段的行，concurrent mode failure 标记会出现在相关阶段行中；这里保留主干并合并为一行）：

2016-08-05T11:02:47.913+0800: 86136.141: [Full GC ... [CMS (concurrent mode failure): 3145727K->2987654K(3145728K), 6.7123456 secs] 4128767K->2987654K(4128768K), [CMS Perm : 87312K->87296K(131072K)], 6.7128765 secs] [Times: user=6.58 sys=0.09, real=6.71 secs]

这一行至少说明三件事：

concurrent mode failure：CMS 的并发周期未能及时完成，随后发生了 STW 的 Full GC；
real=6.71 secs：本次 GC 的墙钟耗时接近 7 秒，与监控上的秒级尖刺相符；
老年代 3145727K->2987654K：约 3G 的老年代回收后仍有约 2.85G 被占用。该次 Full GC 仅回收了少量空间，说明当时大部分对象仍被引用，或至少在本次回收中仍被视为存活对象。后续需要用堆转储确认引用链，不能仅根据类名或占用量断言具体根因。

日志能确定的是：老年代在 Full GC 后仍保持很高的占用，并且 CMS 出现了并发失败。下一步需要确认占用的对象和引用关系。

在项目中验证：jstat 观察，jmap 定位

第一步，jstat 在线观察。 使用 jstat -gcutil <pid> 1000 每秒输出一行，可以观察各代占用和 GC 计数：

  S0     S1     E      O      P     YGC     YGCT    FGC    FGCT     GCT
  0.00  92.31  61.20  88.47  66.53   4213  142.881     17  114.213  257.094

观察四十多分钟后，O（老年代占用）在两次 Full GC 之间持续上升；接近 97% 时，FGC 增加、FGCT 增加数秒，O 只回落到约 95%，随后继续上升。这个周期与监控尖刺一致。jstat 通常开销较低，适合短时间观察，但生产环境仍应确认目标 JVM 可访问，并结合采样周期和业务负载使用。

第二步，jmap 抓现场。 确认老年代高占用后，需要识别对象。在 O 升到约 90%、尖刺尚未发生时，对一台已摘流量的机器执行 jmap -dump:format=b,file=heap.bin <pid>。该操作可能造成较长的 safepoint 停顿，应在低峰并完成流量隔离后执行。同时使用 jmap -histo <pid> 保存直方图快照；它也可能使目标进程进入 safepoint，但通常比导出完整堆转储短。

直方图前列是大量 byte[]、char[] 和 HashMap$Entry，仅凭这些类无法确定持有者。将 dump 文件带回办公机，用 MAT 打开 Dominator Tree，沿最大的 retained heap 查看引用链，最终定位到第 4 篇实现的元数据本地缓存，具体是目录树快照。

还原引用链。 第 4 篇使用读写锁处理 synchronized 全局锁的并发问题，目录树在 ReentrantReadWriteLock 保护下原地变更。目录变更频繁时，写锁独占会让读线程排队，P99 偶尔上升。5 月到 7 月间，目录树缓存改为不可变快照：每小时整点全量重建，后台任务将新目录树载入内存，构建完成后切换缓存引用，读路径不再持有这把锁。第 6 篇的 Kafka 变更消息链路在 6 月才建好，此前没有可靠的变更通知来源，因此当时采用整点全量重建而非逐条增量失效。学习 CMS 时已知道集中创建和替换大对象图需要关注晋升与老年代空间；结合 MAT 的引用链后，项目中的内存压力可归纳为：

整点重建时，大量目录节点集中分配。在多轮 Young GC 中持续存活的对象会晋升到老年代；Survivor 空间不足或动态年龄阈值下降也会增加提前晋升。promotion failed 指老年代无法为晋升对象提供空间，通常会导致更严重的回收或分配失败，不能用它描述 Survivor 区放不下对象的正常晋升。快照顶层的桶数组是否直接分配到老年代，取决于当时的 -XX:PretenureSizeThreshold、收集器和对象大小，不能视为 JVM 的固定规则。
整点切换时，旧快照失去引用，新快照已完成构建。两份快照会在一段时间内同时占用堆，旧快照需要等待后续 GC 才能释放，因此老年代可能短时显著升高。
CMS 的并发回收需要时间。每小时重建持续增加老年代的瞬时压力；当可用空间不足或 CMS 未能及时完成时，就会触发 concurrent mode failure，并产生数秒 STW。这与每小时整点后几分钟出现的尖刺相符。

周期性、多机同时出现和整点触发这三个现象，与目录树重建和 GC 记录一致。排查链路为：监控发现异常，GC 日志确认 Full GC 和高老年代占用，jstat 确认占用变化周期，jmap/MAT 定位缓存快照的引用链。

将结论用于改造：参数与对象分配一起处理

定位后，同时调整 JVM 参数和对象分配方式。参数用于为 CMS 留出更早的回收时机，代码改造处理周期性替换大对象图的问题。两部分都要通过上线后的 GC 日志和 RT 监控验证。

参数调整（脱敏后的大意）。 堆总量保持 4G，将新生代占比从约三分之一调到约一半（NewRatio 从 2 改为 1），并增大 Survivor 区占比。实现上将 SurvivorRatio 调小，因为该参数表示 Eden 与单个 Survivor 区的比值。这样可为短命对象和存活对象复制提供更多新生代空间，是否减少晋升仍需从 GC 日志验证。再将 CMS 触发阈值 CMSInitiatingOccupancyFraction 从接近默认值下调，为并发回收预留更早的启动时机；这会增加 CMS 周期的发生机会，但可降低因启动过晚而发生 concurrent mode failure 的风险。还加入 CMSScavengeBeforeRemark，使 CMS 在重新标记前执行一次 Young GC，目的在于减少重新标记阶段需要处理的新生代引用；对停顿的影响应以实际日志为准。每项参数改动都在预发环境观察至少一天后再推全。

代码改造。 目录树快照从“整点全量重建”改为“增量失效 + 分片加载”：以目录为单位维护缓存项，来自第 6 篇 Kafka 链路的变更消息只失效对应目录分片，读取时加载缺失项。整点全量重建被取消，整体替换大型对象图的操作不再发生，老年代不再因两份完整快照同时存在而周期性升高。分片后的缓存项尺寸较小，仍需通过运行时 GC 数据确认其分配和晋升情况。

效果。 上线后，Full GC 从每小时一到两次降到改造后一周未再出现；Young GC 频率略有上升，但单次停顿在百毫秒以内，监控未显示对应的 RT 异常；P99 的周期性尖刺消失。第 4 篇引入缓存时只评估了并发影响，这次补充了缓存替换时的内存占用和垃圾回收成本。

当时使用的四个工具

本次使用的是 JDK 自带的命令行工具：

jps -l：查找当前用户可见的 JVM 进程，输出 pid 和主类全名，可作为后续命令的输入。
jstat -gcutil pid 1000：观察各代占用百分比、YGC/FGC 次数和累计耗时。它适合判断老年代是否在两次 Full GC 间持续增长，但不能替代 GC 日志和堆转储。
jmap：查看堆内对象。-histo 输出对象数量和大小分布；-dump 导出完整堆供 MAT 离线分析引用链。dump 可能让目标进程进入较长 safepoint，堆越大风险越高，生产环境应先摘流量并选择低峰。
jstack pid：获取线程栈快照。本次没有以它作为主工具；接口长时间无响应、线程池占满或怀疑死锁时，可连续采集多份 jstack 并比较线程状态。

这些工具的使用顺序取决于问题类型。对本例而言，预先学习工具使异常发生后的操作有明确顺序：先通过监控和 GC 日志判断是否为 GC 问题，再用开销较低的 jstat 观察趋势，最后在完成流量隔离后使用 jmap 获取对象和引用链。

当时尚未掌握的部分

这次排查可验证缓存快照与老年代压力的关系，但不代表我已掌握 CMS 的全部行为。以下是当时明确记录的边界。

G1 没有上生产。 G1 收集器在 JDK 7u4 之后已正式可用，其设计目标包括提供可预测的停顿目标，并逐步替代 CMS。2016 年团队能找到的案例和调优资料较少，团队成员也没有实际使用经验，因此主服务仍使用 ParNew + CMS。这是当时的经验和风险约束，不代表 G1 在该场景下不可用。

CMS 的精细调优只到定性理解。 CMSInitiatingOccupancyFraction 的具体取值通过调整后观察得到。我们只掌握了触发过早会增加回收周期、触发过晚会提高 concurrent mode failure 风险这一层定性关系，没有完成参数与工作负载的精确建模。CMS 的内存碎片、promotion failed 和 concurrent mode failure 的差异，当时也没有完全厘清。本次根因在代码侧，参数只起辅助作用；如果只能依靠参数维持运行，现有理解不足以支持稳定调优。

永久代没有出事就没有深入排查。 它存在独立的 OOM 场景，例如类加载过多或大量动态代理。该服务没有遇到这些现象，因此本文没有进一步讨论。

这次排查也说明，GC 日志只能提供回收类型和时间，请求路径与整点任务仍需人工对齐时间戳。将预先学习的 JVM 知识用于项目后，新的限制转到日志记录和关联方式。下一篇记录这部分。

参考资料

《深入理解Java虚拟机》（周志明）内存分代与垃圾收集器章节
JDK 7 官方文档：java 命令行工具（jps / jstat / jmap / jstack）与 CMS 收集器说明
云盘服务端从nodejs 专项 java 相关复盘