05.4 - GC 日志分析
定位: 生产环境中诊断 GC 问题的唯一窗口——没有 GC 日志，排查就是"盲人摸象" 面试高频度: ⭐⭐⭐⭐ 考查方式: 给出 GC 日志让你解读、Full GC 频繁怎么排查、JDK 8 和 JDK 11 的日志区别
一、这是什么？为什么需要它？
**垃圾收集器详解(Serial到ZGC)** 介绍了各收集器的工作原理。但生产环境中的 GC 行为和理论可能完全不同——对象分配速率、Survivor 溢出、过早晋升、并发模式失败等，都需要通过日志来发现。
GC 日志是 JVM 内存行为的黑盒子记录器：
GC 日志的作用域:
┌─────────────────────────────────────────────────────────┐
│ 生产运维链路 │
│ │
│ GC 日志 ──→ GCViewer/GCeasy ──→ 分析报告 ──→ 调优 │
│ ↑ ↑ │
│ 持续的日志记录 发现问题: │
│ (滚动文件, 10份 × 100M) Full GC 频繁 │
│ 停顿时间过长 │
│ CPU 占用过高 │
└─────────────────────────────────────────────────────────┘二、原理拆解
2.1 JDK 8 的 GC 日志格式
JDK 8 使用 -XX:+PrintGCDetails 等独立的参数开关（不同参数控制不同输出）。
bash
# JDK 8 典型 GC 参数
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-XX:+PrintTenuringDistribution
-XX:+PrintGCApplicationStoppedTime
-Xloggc:gc.logMinor GC 日志拆解
2026-06-15T10:00:01.234+0800: 0.456: [GC (Allocation Failure)
[PSYoungGen: 65536K->10240K(76288K)] ← Young: 64M→10M (总76M)
131072K->55768K(251392K), ← 总堆: 128M→54M (总246M)
0.0089732 secs] ← 耗时: 8.9ms
[Times: user=0.03 sys=0.00, real=0.01 secs] ← CPU/真实时间
↑ ↑
时间戳 + JVM 启动后秒数 GC 原因: 分配失败 (Eden 满了)逐字段解读：
[GC (Allocation Failure) ← 原因: 分配失败 (Eden 满)
[PSYoungGen: ← 收集器: Parallel Young
65536K->10240K(76288K)] ← Eden+一个Survivor: 64M→10M (总76M)
131072K->55768K(251392K), ← 整个堆: 128M→54M, 堆总大小 246M
0.0089732 secs] ← 耗时 9ms
[Times: user=0.03 sys=0.00, real=0.01 secs] ← user=CPU 时间, real=墙上时间关键观察：Young 区从 64M 降到 10M（回收了 54M），总堆从 128M 降到 55M（额外回收了来自老年代的 73M？不——这是因为 131072K 是 GC 前的堆占用，但 PSYoungGen 的数值已经包含在总堆中）。
Full GC 日志拆解
2026-06-15T10:01:00.000+0800: 1.567: [Full GC (Ergonomics)
[PSYoungGen: 20480K->0K(76288K)] ← Young 清空
[ParOldGen: 131072K->151552K(175104K)] ← Old: 128M→148M
151552K->151552K(251392K), ← 堆无变化 (对象全部存活)
[Metaspace: 4520K->4520K(1056768K)]
0.5430976 secs] ← 耗时 543ms!
[Times: user=1.43 sys=0.02, real=0.54 secs]关键观察：Full GC 耗时 543ms，是老年代对象太多、需要整理引用导致的。Full GC 后堆占用不变 → 所有对象都存活 → 可能是 OOM 的前兆。
2.2 JDK 9+ 统一 GC 日志
JDK 9 引入 Unified JVM Logging（-Xlog），一个统一的框架管理所有 JVM 日志。
bash
# JDK 9+ 典型 GC 参数
-Xlog:gc*=info:file=gc.log:time,uptime,level,tags:filecount=10,filesize=100M格式说明：
-Xlog:[tag1][,[tag2...]][*][=level] : [output] : [decorators] : [options]
↑ ↑ ↑ ↑
日志标签 输出目标 修饰符 文件策略| 部分 | 说明 | 示例值 |
|---|---|---|
| tag | 日志标签，gc* 表示所有 gc 子标签 | gc, gc+heap, gc+phases, gc+age, gc+ergo |
| level | 日志级别 | info, debug, trace, warning |
| output | 输出目标 | file=gc.log, stdout, stderr |
| decorators | 附加信息 | time（时间）, uptime（启动秒数）, level（级别）, tags（标签） |
| options | 文件策略 | filecount=10,filesize=100M |
常用标签组合
| 标签 | 内容 | 典型用途 |
|---|---|---|
gc* | 所有 GC 相关 | 日常监控 |
gc+heap | GC 前后堆状态 | 查看堆占用 |
gc+phases | GC 内各阶段耗时 | 分析停顿组成 |
gc+age | 对象年龄分布 | Survivor 溢出检查 |
gc+ergo | GC 自适应决策 | 为什么涨 Survivor？ |
gc+promotion | 对象晋升 | 过早晋升检查 |
gc+ref | 引用处理 | Reference 处理耗时 |
gc+stringtable | 字符串表清理 | String Dedup 效果 |
JDK 9+ G1 日志拆解
[2026-06-15T10:00:01.234+0800][0.456s][info][gc,start]
GC(0) Pause Young (Concurrent Start) (G1 Humongous Allocation)
[2026-06-15T10:00:01.234+0800][0.456s][info][gc,task]
GC(0) Using 8 workers of 8 for evacuation
← 8 个 GC 线程并行
[2026-06-15T10:00:01.248+0800][0.470s][info][gc,phases]
GC(0) Pre Evacuate Collection Set: 0.0ms ← 准备阶段
GC(0) Evacuate Collection Set: 10.5ms ← **复制存活对象 10.5ms**
GC(0) Post Evacuate Collection Set: 1.2ms ← 收尾
[2026-06-15T10:00:01.248+0800][0.470s][info][gc,heap]
GC(0) Eden regions: 32->0(15) ← Eden: 32个Region→0个(恢复15个)
GC(0) Survivor regions: 4->5(5) ← Survivor: 4→5个Region
GC(0) Old regions: 120->120 ← Old: 无变化
GC(0) Humongous regions: 2->2 ← 大对象区: 无变化
[2026-06-15T10:00:01.248+0800][0.470s][info][gc,metaspace]
GC(0) Metaspace: 52.1M(67.2M)->52.1M(67.2M) ← 元空间无变化
[2026-06-15T10:00:01.248+0800][0.470s][info][gc]
GC(0) Pause Young (Concurrent Start) 120M->60M(512M) 11.7ms
↑ ↑ ↑ ↑
GC ID GC前→GC后(堆总) 耗时2.3 关键指标
| 指标 | 定义 | 正常范围 | 告警阈值 |
|---|---|---|---|
| GC 频率 | 每分钟 GC 次数 | Young: 1-10 次/分钟 | > 20 次/分钟 |
| YG pause | Young GC 平均停顿 | < 50ms | > 200ms |
| FG pause | Full GC 平均停顿 | < 500ms | > 3s |
| GC 吞吐量 | 应用时间 / (应用+GC) | > 99% | < 95% |
| 晋升速率 | 每分钟移入 Old 的量 | < Old 的 1%/分钟 | > 5%/分钟 |
| 堆占用率 | GC 前堆占用比例 | < 70% | > 85% |
2.4 常见模式与诊断
模式 1: 频繁 Young GC
┌─ 表现: 每几秒一次 Young GC, 每次杀不了多少
├─ 问题: 分配速率太高 (Rate of Allocation)
├─ 诊断: 用 jstat -gcutil 看 Eden 使用率增长速度
└─ 对策: 1) 代码优化（减少不必要的对象创建）
2) 增大 -Xmn (给新生代更多空间)
3) 检查是否 TLAB 浪费
模式 2: Young GC 后老年代很快被占满 (过早晋升)
┌─ 表现: Young GC 后存活对象大量进入 Old
├─ 问题: Survivor 太小, 对象来不及死就晋升了
├─ 诊断: 打开 -XX:+PrintTenuringDistribution
观察 age 分布 → 大部分对象在 age 0-1 就晋升
└─ 对策: 增大 SurvivorRatio → 给 Survivor 更多空间
调高 MaxTenuringThreshold → 让对象在 Young 多待几轮
模式 3: Full GC 频繁
┌─ 表现: Full GC 多次发生, 堆占用居高不下
├─ 问题: 老年代迅速填满
├─ 诊断: 1) 检查晋升速率 (jstat -gc)
2) 检查是否有大对象直接分配到 Old
3) dump 堆分析 (jmap -histo:live)
└─ 对策: 1) 增加 -Xmx
2) 优化代码减少长期对象
3) 检查是否缓存爆炸
模式 4: CMS 并发模式失败
┌─ 表现: "Concurrent Mode Failure" → 串行 Full GC
├─ 问题: 老年代满的速度 > CMS 清理的速度
├─ 诊断: 检查 CMSInitiatingOccupancyFraction → 是否太小？
└─ 对策: 1) 降低 CMSInitiatingOccupancyFraction (提前触发)
2) 增大老年代或堆
3) 考虑切换到 G1
模式 5: 大堆 GC 停顿过长
┌─ 表现: Full GC 停顿 > 10s
├─ 问题: 堆太大, 移动活着对象耗时太长
├─ 诊断: 日志中查看 GC pause duration
└─ 对策: 1) Parallel → G1
2) G1 → ZGC (JDK 11+)
3) 或者把大堆拆成多个进程三、图解全景
GC 日志分析流程图:
收到告警: "GC 时间过长" / "Full GC 频繁"
│
▼
取 GC 日志
│
▼
┌──────────────────────────────────────────────┐
│ 第一步: 看 GC 频率 │
│ grep 'GC (' gc.log | head -100 │
│ 看每两次 GC 之间的间隔 │
│ → 如果 < 1s → 分配速率太高或堆太小 │
└──────────────────────────────────────────────┘
│
▼
┌──────────────────────────────────────────────┐
│ 第二步: 看停顿时间 │
│ 找最长暂停: grep 'Full GC' gc.log │
│ 看 real= 值, 乘以 GC 线程 / 核数 │
│ → 如果 > 3s → 堆太大或老年代收集器不合适 │
└──────────────────────────────────────────────┘
│
▼
┌──────────────────────────────────────────────┐
│ 第三步: 看晋升模式 │
│ jstat -gc <pid> 5000 100 │
│ 观察 Old 区的增速 │
│ → 如果 Old 在 Full GC 后迅速增长 → 过早晋升 │
└──────────────────────────────────────────────┘
│
▼
┌──────────────────────────────────────────────┐
│ 第四步: 对照调优决策树 │
│ → 定位到 [05.5-GC调优参数速查] 找对应方案 │
└──────────────────────────────────────────────┘四、实战验证
演示: 触发 GC 并查看日志
bash
# JDK 8 运行带 GC 日志的应用
java -Xms100m -Xmx100m \
-XX:+PrintGCDetails \
-XX:+PrintGCDateStamps \
-Xloggc:gc-demo.log \
-jar myapp.jarbash
# JDK 17+ 运行带 GC 日志的应用
java -Xms100m -Xmx100m \
-Xlog:gc*=info:file=gc-demo.log:time,uptime,level,tags:filecount=5,filesize=10m \
-jar myapp.jarGCeasy 分析报告关键指标
使用 gceasy.io 上传 GC 日志后，重点关注：
| 指标 | 含义 | 如果异常 |
|---|---|---|
| Throughput | GC 吞吐量 (%) | < 95% → 需要调优 |
| Avg Pause Time | 平均停顿 | > 200ms → 检查收集器 |
| Max Pause Time | 最大停顿 | > 1s → 紧急情况 |
| GC Count | 各类型 GC 次数 | Full GC > 0 → 需分析原因 |
| GC Cause | 停顿原因分析 | Allocation Failure 最常见 |
五、面试视角
| 追问 | 答案要点 |
|---|---|
| 怎么看 GC 日志？ | 三步法：1) 看 GC 频率（间隔时间）；2) 看停顿时间（real=）；3) 看堆占用变化（GC 前后对比）。重点关注 Full GC 次数和每次 GC 后是否有空间被释放 |
| Full GC 频繁怎么分析？ | 先确认是谁触发的 Full GC（日志中的 GC Cause）。常见原因：晋升失败、Metaspace 满、System.gc()、CMS 并发模式失败。然后对照晋升速率、老年代增速来定位 |
| JDK 8 和 JDK 11 的 GC 日志有什么区别？ | JDK 8 用独立参数（-XX:+PrintGCDetails），格式是 [GC [PSYoungGen: ...]；JDK 9+ 统一用 -Xlog:gc*，格式带标签和时间戳 [info][gc,start] |
| 如何打开 GC 日志对性能的影响？ | 极小。GC 日志是异步写入的缓冲区操作。但生产环境要注意：日志文件打满磁盘可能导致 JVM 卡死。用滚动策略（filecount+filesize）控制 |
| 什么是"过早晋升"（Premature Promotion）？ | Survivor 空间不足，对象熬不到 MaxTenuringThreshold 就被迫晋升到老年代。导致老年代快速填满，Full GC 频繁。解决：调大 Survivor 或增大 MaxTenuringThreshold |
| GC 吞吐量怎么算？ | 吞吐量 = 应用运行时间 / (应用运行时间 + GC 总时间)。GC 日志中可以统计所有 GC 的 real 时间之和。99% 以上 = 优秀，95% 以下 = 需要调优 |
| GC 日志中的 user/sys/real 分别代表什么？ | user=GC 线程消耗的 CPU 时间（多线程 > real），sys=系统调用时间，real=墙上时钟时间（实际暂停时长） |
| CMS 日志中的"Concurrent Mode Failure"意味着什么？ | CMS 并发回收速度跟不上应用分配速度，老年代被占满。JVM 放弃 CMS，启用 Serial Old 单线程 Full GC → 停顿时间暴增。根因是老年代预留空间不足或分配速率太高 |
📚 相关链接
- **垃圾收集器详解(Serial到ZGC)** — 各收集器的日志特征不同
- **GC调优参数速查** — 日志参数 + 分析结果后的调优参数
- **OOM排查方法论** — GC 日志是 OOM 排查的第一步
- **FullGC频繁排查方法论** — Full GC 的深度排查流程
- ← 返回 **GC索引**