GC 日志分析实战：读懂每一行 GC 输出

当线上服务出现延迟飙升、CPU 打满、甚至 OOM 之前，GC 日志是最直接的第一手证据。它忠实地记录了每一次垃圾回收的触发原因、暂停时间、内存变化——但前提是你得读得懂。

一组真实数据：某电商大促期间，服务 P99 延迟从 50ms 飙到 2s。运维第一反应是加机器，但打开 GC 日志一看——每隔 40 秒就有一次 1.8 秒的 Full GC。问题不在流量，而在内存泄漏导致的频繁 Full GC。

这篇文章，我们用一个真实的 GC 日志文件，逐行拆解 Young GC、Full GC、Mixed GC 的输出格式，搞清楚每一个字段代表什么。读完之后，你能做到：

• 看懂 GC 日志的每一列含义，不再"凭感觉猜"
• 区分 Young GC / Full GC / Mixed GC 的触发条件
• 用 GC cause 快速定位问题根因
• 掌握 GCViewer、GCEasy 等工具做可视化分析

巧妇难为无米之炊。分析 GC 日志的前提是你得先让它输出。遗憾的是，很多线上环境压根没开 GC 日志，等到出事时只能干瞪眼。

JDK 8 及以前

JDK 8 使用 -XX 系列参数控制 GC 日志输出：

# JDK 8 GC 日志标准配置
java -XX:+PrintGCDetails \
     -XX:+PrintGCDateStamps \
     -XX:+PrintGCTimeStamps \
     -XX:+PrintHeapAtGC \
     -XX:+PrintGCApplicationStoppedTime \
     -Xloggc:/var/log/gc/gc-%t.log \
     -XX:+UseGCLogFileRotation \
     -XX:NumberOfGCLogFiles=10 \
     -XX:GCLogFileSize=20M \
     -jar app.jar

JDK 9+ 统一日志框架

JDK 9 引入了统一日志系统（Unified Logging），用一个 -Xlog 参数搞定所有日志配置：

# JDK 9+ 统一日志配置
java -Xlog:gc*,gc+age=trace,safepoint:file=/var/log/gc/gc-%t.log:time,uptime,level,tags:filecount=10,filesize=20M \
     -jar app.jar

语法结构是 -Xlog:标签:输出目标:装饰器:轮转参数。相比 JDK 8 的散装参数，统一日志更灵活也更强——但在面试中，JDK 8 的参数你仍然要记得，因为大量存量系统还在用。

Young GC（Minor GC）是最频繁发生的 GC 类型。我们拿一条真实的 G1 收集器日志来逐字段拆解：

2024-03-15T14:23:07.392+0800: 128.456: [GC pause (G1 Evacuation Pause) (young), 0.0234567 secs]
   [Eden: 256M(256M)->0B(224M) Survivors: 0B->32M Heap: 512M(1024M)->288M(1024M)]
   [Times: user=0.04 sys=0.01, real=0.02 secs]

关键指标解读

1) GC Cause — 触发原因

日志中的 (G1 Evacuation Pause) 表示这是 G1 的正常 Young GC 疏散暂停。如果是 (Allocation Failure)，说明 Eden 区不够分配新对象了。

2) Eden 区变化：256M(256M)->0B(224M)

格式是 使用量(容量)。GC 前 Eden 用了 256M（容量 256M，已经满了），GC 后清零到 0B。但注意容量从 256M 变成了 224M——G1 会动态调整 Region 数量。

3) Survivors 变化：0B->32M

GC 前 Survivor 区是空的，GC 后存活对象占了 32M。存活率 = 32M / 256M = 12.5%，说明大部分对象都是朝生夕灭的，这是健康状态。

4) Heap 变化：512M(1024M)->288M(1024M)

整个堆从 512M 降到 288M，回收了 224M。堆最大容量是 1024M，还有余量。

5) Times：user=0.04 sys=0.01, real=0.02

user 是所有 GC 线程的 CPU 时间之和（多线程所以比 real 大），real 是实际挂起用户线程的时间。real 才是影响响应延迟的那个数字。

如果说 Young GC 是"例行体检"，Full GC 就是"进了急诊室"。一次 Full GC 的暂停时间通常是 Young GC 的 10~100 倍。

2024-03-15T14:25:12.789+0800: 253.853: [Full GC (Ergonomics)
   [PSYoungGen: 65536K->0K(76288K)]
   [ParOldGen: 173568K->139264K(175104K)]
   239104K->139264K(251392K),
   [Metaspace: 67840K->67840K(1107968K)],
   0.8923456 secs]
   [Times: user=3.42 sys=0.05, real=0.89 secs]

逐字段分析：

• Full GC (Ergonomics)：Ergonomics 表示 JVM 自己判断需要 Full GC（通常是 Young GC 后老年代仍然不够）
• PSYoungGen: 65536K->0K(76288K)：新生代 64M 全部清空
• ParOldGen: 173568K->139264K(175104K)：老年代从 169M 回收到了 136M，只回收了 33M——说明大部分对象确实还在用
• Metaspace: 67840K->67840K：元空间没有任何回收，类都还在加载
• real=0.89 secs：用户线程被暂停了 890 毫秒！这对在线服务是致命的
• user=3.42：4 个 GC 线程并行工作，总计 3.42 秒 CPU 时间，但实际耗时 0.89 秒

常见 GC Cause 对照表

G1 是目前 JDK 的默认收集器（JDK 9+），它的日志比 Parallel GC 复杂得多——因为它引入了 Mixed GC 和 并发标记周期。

Mixed GC — G1 的独门武器

Mixed GC 同时回收新生代和部分老年代 Region，是 G1 避免 Full GC 的关键机制：

2024-03-15T14:30:45.123+0800: 586.187: [GC pause (G1 Evacuation Pause) (mixed), 0.0456789 secs]
   [Eden: 128M(128M)->0B(112M) Survivors: 16M->32M Heap: 896M(2048M)->544M(2048M)]
   [Times: user=0.12 sys=0.01, real=0.05 secs]

关键区别：日志中的 (mixed) 标记。Mixed GC 比纯 Young GC 多回收了一些老年代 Region，所以暂停时间稍长（50ms vs 23ms），但远小于 Full GC。

并发标记周期（Concurrent Cycle）

Mixed GC 不会凭空发生——G1 需要先做一次并发标记，找出哪些老年代 Region 垃圾多、值得回收：

[GC concurrent-root-region-scan-start]
[GC concurrent-root-region-scan-end, 0.0045 secs]
[GC concurrent-mark-start]
[GC concurrent-mark-end, 0.1234 secs]
[GC concurrent-cleanup-start]
[GC concurrent-cleanup-end, 0.0012 secs]

并发标记期间用户线程正常运行（不是 STW），所以日志中没有 pause 时间。整个过程分 4 步：

1. root-region-scan：扫描根 Region（初始标记的后续，STW 很短）
2. mark：并发遍历对象图，标记存活对象（耗时最长，但不暂停）
3. cleanup：计算每个 Region 的垃圾比例，排序回收价值
4. 标记完成后，后续的 Young GC 会变成 Mixed GC

Evacuation Failure — 疏散失败

当 G1 在 Young/Mixed GC 时找不到空闲 Region 来放置存活对象，就会发生疏散失败，日志里会出现刺眼的 to-space exhausted：

2024-03-15T15:02:33.456+0800: [GC pause (G1 Evacuation Pause) (young)
   to-space exhausted, 1.2345678 secs]
   [Eden: 256M(256M)->0B(256M) Survivors: 32M->0B
    Heap: 1920M(2048M)->1890M(2048M)]

暂停时间飙升到 1.2 秒！原因是堆快满了（1920M / 2048M = 93.7%），G1 找不到足够的空闲 Region 来复制存活对象，最终退化成 Full GC。

人肉看 GC 日志适合快速排查，但要做趋势分析、对比优化，你离不开可视化工具。

GCViewer — 本地离线分析利器

开源免费的桌面工具，把 GC 日志拖进去就能看到完整的可视化图表：

• 堆使用趋势线：如果 GC 后堆使用量持续上升（锯齿底部不断抬高），基本可以确认内存泄漏
• 暂停时间柱状图：一眼看到哪些时间点出现了长暂停
• GC 频率统计：Young GC / Full GC 各发生了多少次，总暂停多久

GCEasy — 在线分析平台

上传 GC 日志到 gceasy.io，自动生成分析报告。它会给你一个健康评分，并标注异常指标：

GC Health Score:     65/100  ← 低于 80 就要关注
Avg GC Pause:        45ms    ← 平均暂停时间
Max GC Pause:        1.89s   ← 最大暂停时间（Full GC）
GC Throughput:       97.2%   ← 应用运行时间占比
Promoted Avg:        28MB    ← 平均每次晋升到老年代的大小
Created/sec:         120MB   ← 对象分配速率

jstat — 实时监控 GC 状态

当你没法拿到 GC 日志文件时，jstat 是最后的武器：

# 每 2 秒输出一次 GC 统计，共 100 次
jstat -gc <pid> 2000 100

# 输出示例：
 S0     S1     E      O      M     CCS    YGC   YGCT   FGC   FGCT    GCT
0.0   32.0  128.0  512.0  64.0  5.8   156   3.42    3   2.67   6.09

# 关键字段：
# YGC  = Young GC 次数       YGCT = Young GC 总耗时
# FGC  = Full GC 次数        FGCT = Full GC 总耗时
# GCT  = GC 总耗时（YGC + FGC）
# E    = Eden 使用量(KB)     O    = Old 使用量(KB)

从上面的输出可以算出：

到这里，你已经能读懂绝大多数 GC 日志了。最后，我们把常见的 GC 问题和解决方案整理成一张速查表，然后聊聊怎么建立 GC 监控体系。

常见 GC 问题速查表

生产环境 GC 监控体系

关键监控指标