前言
本文将通过一个真实的生产环境案例，详细展示如何系统性地排查和解决JVM垃圾收集问题。这个案例涵盖了从问题发现、分析诊断到最终解决的完整过程，对于理解JVM调优实战具有重要的参考价值。
系统背景
我们的服务是一个高并发的微服务应用，技术栈如下：
- 应用框架：Spring Boot
- 指标采集：Micrometer
- 监控系统：Datadog
说明：Micrometer 作为应用监控的门面库，支持多种监控系统，包括：AppOptics、Atlas、Datadog、Dynatrace、Elastic、Ganglia、Graphite、Humio、Influx、Instana、JMX、KairosDB、New Relic、Prometheus、SignalFx、Stackdriver、StatsD、Wavefront 等。
详细信息请参考： https://micrometer.io/docs
问题现象
问题描述
在日常监控中，我们发现一个服务节点出现了严重的GC性能问题：
- 最大GC暂停时间：经常超过400ms
- 峰值暂停时间：达到546ms（发生时间：02月04日 09:20:00）
GC暂停时间监控图
业务影响
这种GC暂停时间严重影响了业务运行：
- 服务超时：服务调用超时时间为1秒，GC暂停过长导致超时风险
- 性能要求：
- 最大GC暂停时间 < 200ms
- 平均暂停时间 < 100ms
- 业务冲击：对客户的交易策略产生了严重影响，亟需解决
问题排查过程
第一步：系统资源使用分析
CPU负载分析
首先检查CPU使用情况，监控数据如下：
CPU负载监控图
观察结果：
- 系统负载：4.92
- CPU使用率：约7%
重要提示：这个监控图中实际隐含了重要线索（CPU核心数与GC线程数的不匹配），但当时并未察觉异常。
GC 内存使用情况
然后我们排查了这段时间的内存使用情况：
从图中可以看到，大约 09:25 左右 old_gen 使用量大幅下跌，确实是发生了 FullGC。
但 09:20 前后，老年代空间的使用量在缓慢上升，并没有下降，也就是说引发最大暂停时间的这个点并没有发生 FullGC。
当然，这些是事后复盘分析得出的结论。当时对监控所反馈的信息并不是特别信任，怀疑就是触发了 FullGC 导致的长时间 GC 暂停。
为什么有怀疑呢，因为 Datadog 这个监控系统，默认 10s 上报一次数据。有可能在这 10s 内发生些什么事情但是被漏报了（当然，这是不可能的，如果上报失败会在日志系统中打印相关的错误）。
再分析上面这个图，可以看到老年代对应的内存池是 “ps_old_gen”，通过前面的学习，我们知道，ps 代表的是 ParallelGC 垃圾收集器。
第三步：JVM配置分析
启动参数检查
检查JVM启动参数配置：
-Xmx4g -Xms4g
配置分析：
- JDK版本：JDK 8
- GC选择：未指定，使用默认的ParallelGC
- 堆内存：最大和初始堆内存均为4GB
初步问题假设
怀疑点：ParallelGC可能是问题根源
- 设计目标：ParallelGC主要追求系统最大吞吐量
- 权衡策略：为了吞吐量优化，会牺牲单次GC的暂停时间
- 推测结论：可能因此导致暂停时间过长
第一次优化尝试：切换到G1GC
优化策略选择
选择G1垃圾收集器的理由：
- 稳定性：在JDK 8的新版本中，G1已经相当稳定
- 性能表现：具有良好的延迟控制能力
- 适用场景：更适合低延迟要求的应用
配置过程
初次配置（失败）
# 参数配置错误，导致启动失败
-Xmx4g -Xms4g -XX:+UseG1GC -XX:MaxGCPauseMills=50ms
错误分析：
- 参数名拼写错误：
MaxGCPauseMills→MaxGCPauseMillis - 参数值格式错误：
50ms→50
修正后配置
-Xmx4g -Xms4g -XX:+UseG1GC -XX:MaxGCPauseMillis=50
初步效果验证
服务启动成功，通过健康检测切换到新节点后，监控显示：
G1GC初期效果监控图
效果评估：
- ✅ GC暂停时间：基本控制在50ms以内
- ✅ 符合预期：达到了初期的优化目标
但是，问题远未结束.....
“彩蛋”惊喜
过了一段时间，我们发现了个下面这个惊喜（也许是惊吓），如下图所示：
中奖了，运行一段时间后，最大 GC 暂停时间达到了 1300ms。
情况似乎更恶劣了。
继续观察，发现不是个别现象：
内心是懵的，觉得可能是指标算错了，比如把 10s 内的暂停时间全部加到了一起。
注册 GC 事件监听
于是想了个办法，通过 JMX 注册 GC 事件监听，把相关的信息直接打印出来。
关键代码如下所示：
// 每个内存池都注册监听
for (GarbageCollectorMXBean mbean
: ManagementFactory.getGarbageCollectorMXBeans()) {
if (!(mbean instanceof NotificationEmitter)) {
continue; // 假如不支持监听...
}
final NotificationEmitter emitter = (NotificationEmitter) mbean;
// 添加监听
final NotificationListener listener = getNewListener(mbean);
emitter.addNotificationListener(listener, null, null);
}
通过这种方式，我们可以在程序中监听 GC 事件，并将相关信息汇总或者输出到日志。
再启动一次，运行一段时间后，看到下面这样的日志信息：
{
"duration":1869,
"maxPauseMillis":1869,
"promotedBytes":"139MB",
"gcCause":"G1 Evacuation Pause",
"collectionTime":27281,
"gcAction":"end of minor GC",
"afterUsage":
{
"G1 Old Gen":"1745MB",
"Code Cache":"53MB",
"G1 Survivor Space":"254MB",
"Compressed Class Space":"9MB",
"Metaspace":"81MB",
"G1 Eden Space":"0"
},
"gcId":326,
"collectionCount":326,
"gcName":"G1 Young Generation",
"type":"jvm.gc.pause"
}
情况确实有点不妙。
这次实锤了，不是 FullGC，而是年轻代 GC，而且暂停时间达到了 1869ms。 一点道理都不讲，我认为这种情况不合理，而且观察 CPU 使用量也不高。
找了一大堆资料，试图证明这个 1869ms 不是暂停时间，而只是 GC 事件的结束时间减去开始时间。
打印 GC 日志
既然这些手段不靠谱，那就只有祭出我们的终极手段：打印 GC 日志。
修改启动参数如下：
-Xmx4g -Xms4g -XX:+UseG1GC -XX:MaxGCPauseMillis=50
-Xloggc:gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps
重新启动，希望这次能排查出问题的原因。
运行一段时间，又发现了超长的暂停时间。
分析 GC 日志
因为不涉及敏感数据，那么我们把 GC 日志下载到本地进行分析。
定位到这次暂停时间超长的 GC 事件，关键的信息如下所示：
Java HotSpot(TM) 64-Bit Server VM (25.162-b12) for linux-amd64 JRE (1.8.0_162-b12),
built on Dec 19 2017 21:15:48 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)
Memory: 4k page, physical 144145548k(58207948k free), swap 0k(0k free)
CommandLine flags:
-XX:InitialHeapSize=4294967296 -XX:MaxGCPauseMillis=50 -XX:MaxHeapSize=4294967296
-XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps
-XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC
2020-02-24T18:02:31.853+0800: 2411.124: [GC pause (G1 Evacuation Pause) (young), 1.8683418 secs]
[Parallel Time: 1861.0 ms, GC Workers: 48]
[GC Worker Start (ms): Min: 2411124.3, Avg: 2411125.4, Max: 2411126.2, Diff: 1.9]
[Ext Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 2.7, Diff: 2.7, Sum: 16.8]
[Update RS (ms): Min: 0.0, Avg: 3.6, Max: 6.8, Diff: 6.8, Sum: 172.9]
[Processed Buffers: Min: 0, Avg: 2.3, Max: 8, Diff: 8, Sum: 111]
[Scan RS (ms): Min: 0.0, Avg: 0.2, Max: 0.5, Diff: 0.5, Sum: 7.7]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3]
[Object Copy (ms): Min: 1851.6, Avg: 1854.6, Max: 1857.4, Diff: 5.8, Sum: 89020.4]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.6]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 48]
[GC Worker Other (ms): Min: 0.0, Avg: 0.3, Max: 0.7, Diff: 0.6, Sum: 14.7]
[GC Worker Total (ms): Min: 1858.0, Avg: 1859.0, Max: 1860.3, Diff: 2.3, Sum: 89233.3]
[GC Worker End (ms): Min: 2412984.1, Avg: 2412984.4, Max: 2412984.6, Diff: 0.5]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 1.5 ms]
[Other: 5.8 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 1.7 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 1.1 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 2.3 ms]
[Eden: 2024.0M(2024.0M)->0.0B(2048.0K)
Survivors: 2048.0K->254.0M
Heap: 3633.6M(4096.0M)->1999.3M(4096.0M)]
[Times: user=1.67 sys=14.00, real=1.87 secs]
前后的 GC 事件都很正常，也没发现 FullGC 或者并发标记周期，但找到了几个可疑的点。
physical 144145548k(58207948k free)：JVM 启动时，物理内存 137GB，空闲内存 55GB。[Parallel Time: 1861.0 ms, GC Workers: 48]：垃圾收集器工作线程 48 个。
GC 日志中揭露了几个关键信息，
user=1.67：用户线程耗时 1.67s；sys=14.00：系统调用和系统等待时间 14s；real=1.87 secs：实际暂停时间 1.87s；- GC 之前，年轻代使用量 2GB，堆内存使用量 3.6GB，存活区 2MB，可推断出老年代使用量 1.6GB；
- GC 之后，年轻代使用量为 0，堆内存使用量 2GB，存活区 254MB，那么老年代大约 1.8GB，那么“内存提升量为 200MB 左右”。
这样分析之后，可以得出结论：
- 年轻代转移暂停，复制了 400MB 左右的对象，却消耗了 1.8s，系统调用和系统等待的时间达到了 14s。
- JVM 看到的物理内存 137GB。
- 推算出 JVM 看到的 CPU 内核数量 72个，因为 GC 工作线程
72* 5/8 ~= 48个。
看到这么多的 GC 工作线程我就开始警惕了，毕竟堆内存才指定了 4GB。
按照一般的 CPU 和内存资源配比，常见的比例差不多是 4 核 4GB、4 核 8GB 这样的。
看看对应的 CPU 负载监控信息：
通过和运维同学的沟通，得到这个节点的配置被限制为 4 核 8GB。
这样一来，GC 暂停时间过长的原因就定位到了：
- K8S 的资源隔离和 JVM 未协调好，导致 JVM 看见了 72 个 CPU 内核，默认的并行 GC 线程设置为
72* 5/8 ~= 48 个，但是 K8S 限制了这个 Pod 只能使用 4 个 CPU 内核的计算量，致使 GC 发生时，48 个线程在 4 个 CPU 核心上发生资源竞争，导致大量的上下文切换。
处置措施为：
- 限制 GC 的并行线程数量
事实证明，打印 GC 日志确实是一个很有用的排查分析方法。
限制 GC 的并行线程数量
下面是新的启动参数配置：
-Xmx4g -Xms4g
-XX:+UseG1GC -XX:MaxGCPauseMillis=50 -XX:ParallelGCThreads=4
-Xloggc:gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps
这里指定了 -XX:ParallelGCThreads=4，为什么这么配呢？我们看看这个参数的说明。
-XX:ParallelGCThreads=n
设置 STW 阶段的并行 worker 线程数量。 如果逻辑处理器小于等于 8 个，则默认值 n 等于逻辑处理器的数量。
如果逻辑处理器大于 8 个，则默认值 n 大约等于处理器数量的 5/8。在大多数情况下都是个比较合理的值。如果是高配置的 SPARC 系统，则默认值 n 大约等于逻辑处理器数量的 5/16。
-XX:ConcGCThreads=n
设置并发标记的 GC 线程数量。默认值大约是 ParallelGCThreads 的四分之一。
一般来说不用指定并发标记的 GC 线程数量，只用指定并行的即可。
重新启动之后，看看 GC 暂停时间指标：
红色箭头所指示的点就是重启的时间点，可以发现，暂停时间基本上都处于 50ms 范围内。
后续的监控发现，这个参数确实解决了问题。
案例总结与思考
核心经验
通过这个完整的排查案例，我们可以得到以下重要经验：没有量化，就没有改进。JVM问题排查和性能调优必须基于具体的监控数据进行。
使用的排查手段
本案例运用了以下关键技术手段：
- 指标监控：通过Micrometer + Datadog建立完整的监控体系
- ⚙️ JVM参数调优：合理配置启动内存和垃圾收集器
- GC日志分析：深入分析GC日志定位根本原因
- JMX事件监听：通过编程方式获取详细的GC事件信息
GC性能维度评估
延迟维度：
- 主要关注GC暂停时间
- 目标：最大暂停时间 < 200ms，平均暂停时间 < 100ms
吞吐量维度：
- 业务线程CPU资源占用百分比
- GC影响因素：暂停时间 + 并发GC的CPU消耗
系统容量维度：
- 硬件配置合理性
- 服务处理能力匹配度
关键技术洞察
容器化环境的特殊挑战：
- 容器资源限制与JVM感知的不匹配
- GC线程数配置需要与实际可用CPU核心数对齐
- K8s资源隔离机制需要与JVM参数协调配置
问题排查的系统性方法：
- 现象观察 → 通过监控发现异常
- 假设验证 → 基于经验提出问题假设
- 深入分析 → 通过日志等手段验证假设
- 解决方案 → 针对根因制定解决措施
- 效果验证 → 持续监控验证解决效果
只要确保各项性能指标满足业务需求，资源占用保持在合理范围内，就达到了JVM调优的预期目标。