3. GC日志详解：如何开启GC日志，日志格式解读

GC日志，说白了就是JVM的"黑匣子"。我入行那会儿，线上服务一卡顿，第一反应就是抓GC日志来看——这习惯我一直保持到现在。你想想看，没有日志，你连GC到底发生了什么都不知道，优化和排查根本无从下手。

这一章，咱们就聊聊怎么把GC日志打开，以及不同垃圾收集器的日志该怎么读。我会把Parallel、CMS、G1这三种最常见的收集器日志格式掰开来讲，配合我在项目里踩过的坑。

核心观点： GC日志是诊断GC抖动和内存泄漏的第一手证据。看不懂日志，后面的调优就是盲人摸象。

3.1 开启GC日志——这几行参数不能少

我个人习惯，只要上线的Java应用，不管环境多紧张，GC日志一定要开。为啥？因为等到出问题了再想开，已经来不及了。日志不占多少磁盘，带来的信息价值远超成本。

不同JDK版本，开启方式略有差异。但核心参数是下面这几组：


# JDK 8 及更早版本（最经典的组合）
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-XX:+PrintGCTimeStamps
-Xloggc:/path/to/gc.log

# JDK 11+ 统一日志（推荐）
-Xlog:gc*:file=/path/to/gc.log:time,uptime,level,tags

参数解析：

参数 作用 我的建议
-XX:+PrintGCDetails 输出GC的详细信息，包括堆各区域变化 必加，少了这个等于没开
-XX:+PrintGCDateStamps 打印日期时间戳（如 2025-01-15T10:30:00） 建议加上，排查问题时方便对时间
-XX:+PrintGCTimeStamps 打印JVM启动后的秒数 也建议加，配合日期戳一起用
-Xloggc:文件路径 指定GC日志的输出文件 不要用相对路径，踩过坑
-Xlog:gc*:file=... (JDK 11+) 新式统一日志，更灵活 JDK 11+ 推荐用这个
曾经踩过的坑： 我曾经在生产环境忘了加 -XX:+PrintGCDateStamps，结果排查问题时，只有JVM启动后的秒数，没有具体日期。服务是凌晨重启的，我硬是算了半天才知道那次GC发生在几点……从那以后，日期戳我必加。

3.2 日志格式总览——先看懂骨架

不论哪种收集器，GC日志都有统一的"骨架"。说白了就是：什么时间 + 什么位置 + 什么原因 + 回收了多少 + 耗时多少。

来看看这个通用模板：


[GC类型] [GC原因] [堆空间信息] [耗时]

举个例子，这是一行典型的Parallel GC日志：


2025-01-15T10:30:00.123+0800: 123.456: [GC (Allocation Failure) [PSYoungGen: 51200K->6144K(59392K)] 102400K->57344K(196608K), 0.0123456 secs] [Times: user=0.02 sys=0.01, real=0.01 secs]

拆开来看：

  • 2025-01-15T10:30:00.123+0800 — 日期时间戳
  • 123.456 — JVM启动后的秒数
  • GC (Allocation Failure) — GC类型（Minor GC）和原因（分配失败）
  • PSYoungGen: 51200K->6144K(59392K) — 年轻代回收前后大小 / 总大小
  • 102400K->57344K(196608K) — 堆回收前后大小 / 总大小
  • 0.0123456 secs — 耗时
  • [Times: user=0.02 sys=0.01, real=0.01 secs] — CPU时间和实际时间
小技巧： 看GC日志，我一般先扫"real"那列。如果real时间远小于user+sys，说明GC在并行执行，这是好事。如果real接近user+sys甚至更大，说明GC发生了STW（Stop-The-World）并且串行执行，要警惕。

3.3 Parallel GC日志解读——吞吐量优先

Parallel GC是JDK 8默认的收集器。它的日志特点就是"实在"，信息直接摆出来，不绕弯子。

Minor GC 示例：


2025-01-15T10:30:01.000+0800: 124.000: [GC (Allocation Failure) [PSYoungGen: 51200K->6144K(59392K)] 102400K->57344K(196608K), 0.0150000 secs] [Times: user=0.03 sys=0.01, real=0.02 secs]

Full GC 示例：


2025-01-15T10:30:02.000+0800: 125.000: [Full GC (Metadata GC Threshold) [PSYoungGen: 6144K->0K(59392K)] [ParOldGen: 51200K->51200K(137216K)] 57344K->51200K(196608K), [Metaspace: 20480K->20480K(20480K)], 0.2500000 secs] [Times: user=0.45 sys=0.05, real=0.25 secs]
关键字段 含义 正常值参考
PSYoungGen 前后变化 年轻代回收效果 回收后剩余应小于回收前20%
堆总变化 整个堆的内存变化 Full GC后堆使用率应显著下降
real 时间 实际STW时间 Minor GC < 50ms，Full GC < 200ms
实战经验： 我在一个批处理系统里遇到过Parallel GC的"吞吐量陷阱"。乍一看GC频率不高，每次耗时也不长，但业务高峰期就是一卡一卡的。后来发现是堆开得太大了，GC虽然次数少，但每次STW时间都接近100ms，对于要求毫秒级响应的后台任务来说，这已经算"抖动"了。

3.4 CMS GC日志解读——低延迟的代价

CMS收集器已经老了，但存量系统里还有很多。它的日志比Parallel复杂，因为你得关注它的每个阶段。

一段典型的CMS日志：


2025-01-15T10:30:03.000+0800: 126.000: [GC (CMS Initial Mark) [1 CMS-initial-mark: 102400K(262144K)] 108544K(327680K), 0.0050000 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
2025-01-15T10:30:03.005+0800: 126.005: [CMS-concurrent-mark-start]
2025-01-15T10:30:03.105+0800: 126.105: [CMS-concurrent-mark: 0.100/0.100 secs] [Times: user=0.20 sys=0.05, real=0.10 secs]
2025-01-15T10:30:03.105+0800: 126.105: [CMS-concurrent-preclean-start]
2025-01-15T10:30:03.115+0800: 126.115: [CMS-concurrent-preclean: 0.010/0.010 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
2025-01-15T10:30:03.115+0800: 126.115: [GC (CMS Final Remark) [YG occupancy: 6144K(65536K)] [1 CMS-remark: 102400K(262144K)] 108544K(327680K), 0.0200000 secs] [Times: user=0.03 sys=0.01, real=0.02 secs]
2025-01-15T10:30:03.135+0800: 126.135: [CMS-concurrent-sweep-start]
2025-01-15T10:30:03.235+0800: 126.235: [CMS-concurrent-sweep: 0.100/0.100 secs] [Times: user=0.15 sys=0.05, real=0.10 secs]

关键阶段解读：

  • CMS Initial Mark — 初始标记，STW，标记GC Roots直接引用的对象。时间很短，一般几毫秒。
  • CMS-concurrent-mark — 并发标记，与应用线程同时运行，标记所有可达对象。这里要关注"耗时"。
  • CMS-concurrent-preclean — 并发预清理，处理一些引用更新，减少Final Remark的负担。
  • CMS Final Remark — 最终标记，STW，处理并发阶段的变化。如果这个阶段耗时突然变长，说明并发标记期间对象变化剧烈。
  • CMS-concurrent-sweep — 并发清扫，回收死对象占用的空间。
曾经踩过的坑： 我曾经在一个电商后台发现CMS的"Concurrent Mode Failure"频繁出现。日志里直接打出了 [CMS CMS-concurrent-mark: 0.500/0.500 secs] [Times: user=1.20 sys=0.30, real=0.50 secs]，然后紧接着就是一次Full GC。为什么会这样？因为老年代碎片太多，并发回收速度跟不上分配速度，CMS只能退化成Serial Old做Full GC。那次以后，我学会了监控老年代碎片率，超过70%就提前触发一次CMS回收。

3.5 G1 GC日志解读——分区管理，一目了然

G1现在是JDK 11+的默认收集器，也是我们的重点。它的日志结构跟Parallel、CMS都有所不同，因为它把堆划分成了多个Region。

一段G1 Young GC日志：


2025-01-15T10:30:04.000+0800: 127.000: [GC pause (G1 Evacuation Pause) (young), 0.0150000 secs]
   [Eden: 512.0M(512.0M)->0.0B(512.0M) Survivors: 0.0B->16.0M Heap: 1024.0M(2048.0M)->528.0M(2048.0M)]
   [Times: user=0.03 sys=0.01, real=0.02 secs]

一段G1 Mixed GC日志：


2025-01-15T10:30:05.000+0800: 128.000: [GC pause (G1 Evacuation Pause) (mixed), 0.0350000 secs]
   [Eden: 512.0M(512.0M)->0.0B(512.0M) Survivors: 16.0M->16.0M Heap: 1024.0M(2048.0M)->480.0M(2048.0M)]
   [Times: user=0.06 sys=0.02, real=0.04 secs]

G1日志关键指标：

字段 含义 关注点
Eden 变化 Eden区回收前后，一般会归零 如果Eden没归零，说明这次GC没回收干净
Survivors 变化 存活对象从Eden晋升到Survivor Survivor大小是否稳定，有没有频繁晋升到老年代
Heap 总变化 整个堆的使用情况 Mixed GC后堆使用率下降是否明显
real 时间 STW耗时 G1目标是尽量控制在10ms以内，超过50ms算异常
我的经验： G1日志里有一个容易被忽略的字段——to-space overflow。如果你在日志里看到类似 to-space exhausted 或者 evacuation failure，说明G1在回收时发生了"疏散失败"，对象无法从源Region复制到目标Region。这时候GC会退化成"标记-压缩"，STW时间会飙升。我遇到过一次，是因为一个定时任务每秒生成几百MB的临时对象，把G1的预留空间打穿了。解决方案是调大 -XX:G1ReservePercent，或者优化任务的批处理大小。

3.6 三种收集器日志对比——一张表看透

为了方便你快速对照，我把三种收集器的日志差异整理了一下：

维度 Parallel GC CMS GC G1 GC
日志行结构 单行，信息紧凑 多行，每个阶段一行 单行+阶段信息混合
关注重点 Young/Full GC次数和耗时 并发阶段耗时 + Final Remark耗时 Pause时间 + Region晋升情况
Full GC标识 直接打印 [Full GC] Concurrent Mode Failure 后触发 标记为 [Full GC (Allocation Failure)] 或 evacuation failure
STW特点 每次GC都STW，但并行执行 初始标记和最终标记STW，并发阶段不STW Young/Mixed GC都STW，但时间短
最危险信号 Full GC 频繁 Concurrent Mode Failure to-space exhausted / evacuation failure
一句话总结： Parallel看次数和总耗时，CMS看并发阶段是否正常完成，G1看单次STW时间和是否发生疏散失败。

3.7 知识体系：GC日志分析全景图

下面这张图，我把GC日志分析的整个流程串了起来。从日志开启、收集器类型识别，到关键指标提取、异常信号捕捉，最后到决策建议。你可以把它当成一个"检查清单"来用。

GC日志分析全景图 开启GC日志 识别收集器类型 Parallel GC 日志 CMS GC 日志 G1 GC 日志 次数 / 耗时 / 堆变化 / Full GC频率 并发阶段耗时 / Final Remark / CMS失败 STW耗时 / Region晋升 / to-space 异常信号捕捉 调优决策与避坑指南

3.8 实用工具——让日志分析不再痛苦

光靠肉眼去翻GC日志，说实话效率太低了。我常用的几个工具，你可以在实际工作中参考：

  • GCeasy — 在线分析工具，上传gc.log就能自动生成报表，一眼看出GC频率、STW时间、内存变化趋势。我每次线上排查先用它扫一遍。
  • GCViewer — 开源工具，可以本地运行，支持多种收集器的日志格式。适合做长时间序列的分析。
  • jstat — JDK自带的命令行工具，适合在服务器上快速看一眼当前GC状况。命令：jstat -gcutil <pid> 1000 10
小建议： 不管用哪种工具，都要先把原始日志保留好。工具分析的是"加工后的信息"，有时候会漏掉一些细节——比如CMS的Concurrent Mode Failure日志里那个具体的触发阈值，工具可能不会高亮显示，但原始日志里看得一清二楚。
← 上一章 📖 返回目录 下一章 →