实习生问我：这堆 GC 日志到底看什么
4 月底，团队来了个实习生。有次他看到我电脑上的 gc.log，问了一句："这一行行的数字，你是怎么看出问题的？"
2021-04-28T09:14:22.118+0800: 341882.221: [GC (Allocation Failure)
[PSYoungGen: 2097152K->261120K(2446848K)] 5242880K->3407872K(7340032K),
0.1842210 secs] [Times: user=0.41 sys=0.02, real=0.18 secs]
我说看多了就知道。他说那能不能讲讲。于是我整理了一遍，顺便把两个工具的用法也写了下来。
第一步：先把日志配对
很多人上来就说"我的 GC 日志没法分析"，其实是日志格式没配全，关键信息缺失。
JDK 8
-XX:+PrintGCDetails # 必须，输出详细 GC 信息
-XX:+PrintGCDateStamps # 输出日期时间戳，没有它只有相对时间
-XX:+PrintGCApplicationStoppedTime # 输出应用暂停时间，很重要
-XX:+PrintTenuringDistribution # 输出对象年龄分布，排查过早晋升时有用
-Xloggc:/data/logs/gc.log
-XX:+UseGCLogFileRotation # 日志切割，不配的话单文件会无限涨
-XX:NumberOfGCLogFiles=10
-XX:GCLogFileSize=64M
JDK 11（统一日志框架）
-Xlog:gc*:file=/data/logs/gc.log:time,uptime,level,tags:filecount=10,filesize=64m
这行的结构是 -Xlog:<标签>:文件名:<装饰器>:<输出选项>。gc* 表示所有 gc 相关标签，time,uptime,level,tags 是四个装饰器。
注意：JDK 9 之后 PrintGCDetails 这些参数会被警告但还能用，JDK 11 上会打一行 "Ignoring option..."，别以为是配置生效了。
两个工具怎么用
GCViewer：本地跑，看趋势图
开源工具，读 GC 日志画成图表。下载地址是 GitHub 的 chewiebug/GCViewer，我们用的是 1.36 版本。
$ java -jar gcviewer-1.36.jar gc.log
打开后最关键的是这几块：
- 堆使用曲线图：红色是总堆、蓝色是年轻代、黑色（深灰）是老年代。健康的老年代曲线应该是锯齿状——慢慢涨上去，一次 Full GC 或 Mixed GC 后掉下来。
- Summary 面板：Throughput、Number of GC pauses、Number of full GC、Max pause。这几个数字是判断健康度的核心。
- Pause 面板：所有停顿时间的分布，看有没有长尾。
GCViewer 的优势是日志不出公司，本地就能看，也不需要联网。缺点是它对新版本 JDK 的日志格式支持会滞后，JDK 11 的日志它经常解析报错，JDK 8 的兼容性最好。
GCeasy：在线上传，出报告
gceasy.io，把 gc.log 拖进去，等一两分钟出一份 HTML 报告。免费版够用（有文件大小限制）。
报告里我最常看的是这几个部分：
- JVM Memory Size：堆各区域的分配情况，一眼看出年轻代是不是太小
- Key Performance Indicators：Throughput、Latency（avg / P99 / max）、Footprint
- GC Statistics：各类型 GC 的次数和耗时占比
- GC Causes：触发 GC 的原因分布，这个非常有用
- Object Stats：分配速率和晋升速率
提醒一句：GC 日志里可能包含类名、包名、文件名等信息。上传到外部网站前，需要确认公司的安全规定。我们的做法是只在需要深入分析时用，且先脱敏——把包名替换掉再传。
三个必须看懂的指标
1. Throughput（吞吐量）
Throughput = (1 - GC总时间 / 应用运行总时间) × 100%
判断标准：
| Throughput | 结论 |
|---|---|
| ≥ 99% | 健康 |
| 95% ~ 99% | 可以接受，但值得看一眼 |
| 90% ~ 95% | 有问题，GC 吃掉太多时间 |
| < 90% | 严重，必须优化 |
2. GC Causes（触发原因）
这是我个人最看重的部分。GCeasy 会统计每种触发原因的次数：
Cause Count Avg Time Total Time
Allocation Failure 48,213 0.061 s 2,941 s
System.gc() 182 1.842 s 335 s
Metadata GC Threshold 12 0.412 s 5 s
Allocation Failure 是年轻代空间不够，正常。但看到 System.gc() 就要警惕了——下面会讲。看到 Metadata GC Threshold 说明元空间不够，要调 -XX:MaxMetaspaceSize。
3. Allocation Rate 和 Promotion Rate
Allocation Rate: 842 MB/s
Promotion Rate: 31 MB/s
分配速率 842 MB/s 说明这个服务在疯狂造对象。晋升速率 31 MB/s 意味着每秒有 31 MB 对象进入老年代，那 -Xmx4g 的堆里老年代 2.8 GB，90 秒就会被填满，必然频繁 Full GC。
看到这种数字，方向就明确了：要么减少对象分配（复用、避免循环里 new），要么加大堆，要么调低晋升年龄让对象在年轻代多呆一会儿。
五种经典异常模式
模式一：内存泄漏
特征：Full GC 后老年代几乎不下降，老年代使用量呈阶梯上升
[Full GC (Ergonomics) [PSYoungGen: 0K->0K(1398272K)]
[ParOldGen: 5242878K->5242871K(5242880K)] 5242878K->5242871K(6641152K), 4.8123411 secs]
回收了 4.8 秒，老年代从 5242878K 降到 5242871K，只回收了 7 KB。这就是典型的内存泄漏——对象被引用着，GC 收不掉。
我们 3 月遇到过一次，最后用 jmap -histo 定位到一个静态 Map 在不断 put 从不 remove：
$ jmap -histo:live 12871 | head -20
num #instances #bytes class name
----------------------------------------------
1: 3421881 273750480 [Ljava.util.HashMap$Node;
2: 3412042 163777984 java.util.HashMap$Node
3: 3409881 109116192 com.xxx.RuleNode
模式二：concurrent mode failure
[CMS-concurrent-mark: 1.842/1.843 secs]
[GC (CMS Final Remark) ...]
[CMS-concurrent-abortable-preclean: 0.021/1.204 secs]
[GC (Allocation Failure) [ParNew (promotion failed): ...]
(concurrent mode failure): ...
含义：CMS 还在并发标记，业务线程已经把老年代填满了。CMS 只能退化成 Serial Old 单线程 Full GC，停顿会以秒计。
解决办法：让 CMS 更早启动，调 -XX:CMSInitiatingOccupancyFraction（默认 92，我们调到 70），或者干脆换 G1。我们后来换了 G1，这个问题彻底没了。
模式三：System.gc() 触发
[Full GC (System.gc()) [PSYoungGen: 412K->0K(1398272K)]
[ParOldGen: 3241881K->882341K(5242880K)] ... 3.4182210 secs]
代码里有人调了 System.gc()，或者依赖的库调了（比如 RMI、SunNioBuffers、某些老版本的 Netty）。每次都是一次 Full GC。
最直接的办法是禁用：
-XX:+DisableExplicitGC
但这个参数要小心：如果你用了堆外内存或 NIO 的 DirectBuffer，System.gc() 是触发回收堆外内存的途径之一，禁用后堆外内存可能涨。更稳妥的是：
-XX:+ExplicitGCInvokesConcurrent # 让 System.gc() 走并发 GC 而不是 Full GC
我们用的是后者。
模式四：年轻代太小
特征：Young GC 极其频繁（每秒好几次），但每次耗时很短（几毫秒）
[GC (Allocation Failure) [PSYoungGen: 699084K->1023K(699392K)], 0.0088121 secs]
[GC (Allocation Failure) [PSYoungGen: 699112K->2046K(699392K)], 0.0091042 secs]
[GC (Allocation Failure) [PSYoungGen: 699231K->1536K(699392K)], 0.0089341 secs]
每 8 毫秒一次，连续不断。GC 本身很快，但频率太高导致总停顿累积，而且对象在年轻代待不住就被晋升到老年代（过早晋升），最终引发 Full GC。
解法是加大年轻代：-Xmn 或者调 -XX:NewRatio。我们把这个服务从 NewRatio=2 改成 NewRatio=1（年轻代占堆的一半），Young GC 频率从每秒 120 次降到每秒 14 次。
模式五：元空间
[Full GC (Metadata GC Threshold) [PSYoungGen: 882K->0K(1398272K)]
[ParOldGen: 341882K->341880K(5242880K)] ... [Metaspace: 262141K->262141K(262144K)]
Metaspace 满了。原因通常是类加载器泄漏（热部署、反射、动态代理）。如果是正常业务，说明 -XX:MaxMetaspaceSize 设小了，默认是不限制（受物理内存限制）。
我们给所有服务都显式设了 -XX:MaxMetaspaceSize=512m，避免它偷偷吃掉系统内存。
一份实测报告的例子
这是我们商品服务一次真实的分析结果，用 GCeasy 出的报告：
Throughput 97.2%
Avg Pause GC Time 62 ms
Max Pause GC Time 4.31 s
GC Causes: Allocation Failure (48,213), System.gc() (182)
Heap after GC: 3.4 GB / 8 GB
Allocation Rate 842 MB/s
Promotion Rate 31 MB/s
三个问题一眼可见：Throughput 97.2% 偏低、有 182 次 System.gc()、最大停顿 4.31 秒。
对应三个动作：加 -XX:+ExplicitGCInvokesConcurrent；改 NewRatio=1；把 CMS 换成 G1。改完一周后重新分析：
Throughput 99.4%
Avg Pause GC Time 41 ms
Max Pause GC Time 312 ms
System.gc() 次数 0（走并发了）
最大停顿从 4.31 秒到 312 毫秒，去掉了那些 System.gc() 导致的长尾。
小结
- 日志配置：JDK 8 用
PrintGCDetails那一套，JDK 11 用-Xlog:gc*:file=...。都记得配日志切割，不然单文件涨到几十 GB。 - GCViewer 本地跑看趋势图，JDK 8 日志兼容性最好；GCeasy 在线出报告更细致，但注意日志脱敏。
- 三个核心指标：Throughput（低于 95% 有问题）、GC Causes（看触发原因分布）、Allocation/Promotion Rate（看对象造得多快）。
- 五种异常模式：内存泄漏（Full GC 后不降）、concurrent mode failure（CMS 来不及）、System.gc()（显式调用）、年轻代太小（高频短停顿）、元空间。
- 建议所有服务都显式设
-XX:MaxMetaspaceSize。
我把这份东西整理成 wiki 发给实习生，他看完写的第一句笔记是："原来 GC 日志不是用来背的，是用来对比的。"我觉得这句话挺对的——单独看一份日志很难判断好坏，改之前和改之后各存一份，对着看差别，进步最快。