第3章 GC日志解读

第3章：GC日志解读：GC日志格式、GC事件类型、GC停顿分析

好，咱们进入正题。GC日志，说白了就是JVM的“黑匣子”。你系统一卡，内存一飙，第一反应是什么？我反正第一件事就是去翻GC日志。它不会骗你，每一行都记录着JVM当时的状态。

很多人觉得GC日志看着头疼，一堆字母和数字。其实没那么复杂。今天我就带你把它拆开揉碎，看完你也能一眼看出问题。

3.1 GC日志格式：你得先看懂它长什么样

先看一个最典型的GC日志行。我随便从项目里摘一段：

2024-01-15T10:30:15.123+0800: 2.456: [GC (Allocation Failure) [PSYoungGen: 1024K->512K(1536K)] 2048K->1024K(4096K), 0.0034567 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]

别慌，咱们一行一行拆。我个人习惯把它分成三段来看：

时间戳部分：2024-01-15T10:30:15.123+0800: 2.456 —— 前面是绝对时间，后面是JVM启动后的相对时间（秒）。这个相对时间很有用，能看出GC发生的频率。
GC事件描述：[GC (Allocation Failure) [PSYoungGen: 1024K->512K(1536K)] 2048K->1024K(4096K), 0.0034567 secs] —— 这里包含了GC类型、原因、各代内存变化、耗时。
停顿时间：[Times: user=0.01 sys=0.00, real=0.00 secs] —— user是用户态CPU时间，sys是内核态，real是实际挂起时间。

重点看real时间。这就是你的应用线程被“冻住”的时长。real如果远小于user+sys，说明是多核并行回收；如果real接近user+sys，那就是单线程在干活。

嗯，这里要注意：不同GC收集器的日志格式略有差异，但核心信息都一样。你只要抓住“回收前→回收后→总容量”这个三元组，基本就能看懂。

3.2 GC事件类型：分清“小扫除”和“大扫除”

GC事件类型，我一般分成三类：Minor GC、Major GC、Full GC。但实际日志里，你看到的可能是更具体的名字。

日志关键字	实际含义	影响范围
`[GC (Allocation Failure)`	Minor GC，年轻代满了	只回收年轻代，通常很快
`[GC (Metadata GC Threshold)`	元空间触发的GC	可能涉及Full GC
`[Full GC (Metadata GC Threshold)`	元空间导致的Full GC	整个堆+元空间
`[Full GC (Ergonomics)`	JVM自动触发的Full GC	整个堆，通常是大问题
`[Full GC (System.gc())`	代码里调了System.gc()	整个堆，要警惕

我遇到过最坑的一次，就是线上频繁Full GC，日志里全是System.gc()。查了半天，发现是某个RPC框架的Netty版本里默认调了System.gc()。你想想看，一个框架偷偷帮你做Full GC，这谁受得了？

避坑指南：我曾经在排查一个内存泄漏时，发现日志里全是Full GC (Allocation Failure)。当时以为是对象太多，结果发现是堆太小。所以看到Full GC别急着加内存，先看是不是代码问题。

3.3 GC停顿分析：你的应用到底“卡”了多久

GC停顿，就是STW（Stop-The-World）。说白了，就是JVM把所有的应用线程都暂停，专心搞垃圾回收。这个停顿时间，直接决定了你的接口响应时间会不会飙升。

怎么分析停顿？我一般看三个指标：

单次停顿时间：看real那一列。如果每次停顿都超过100ms，用户就能感知到卡顿。超过1秒，基本就是事故了。
停顿频率：看两次GC之间的间隔。如果每几秒就来一次Minor GC，说明年轻代太小或者对象创建太快。
总停顿时间占比：这个需要自己算。比如运行10分钟，GC总停顿了30秒，那占比就是5%。超过10%就要警惕了。

举个例子，假设你看到这样的日志：

2024-01-15T10:30:15.123+0800: 2.456: [GC (Allocation Failure) ... 0.0034567 secs]
2024-01-15T10:30:15.130+0800: 2.463: [GC (Allocation Failure) ... 0.0041234 secs]
2024-01-15T10:30:15.138+0800: 2.471: [GC (Allocation Failure) ... 0.0039876 secs]

看到了吗？每隔7ms就来一次Minor GC。虽然每次只有3-4ms，但频率太高了。这说明什么？说明年轻代太小，对象刚分配就满了。我建议你调大-Xmn或者调整-XX:SurvivorRatio。

我的小技巧：分析停顿时间时，别只看平均值。要看P99甚至P99.9。有一次我遇到一个系统，平均GC停顿只有50ms，但P99是500ms。为什么？因为偶尔一次Full GC把平均值拉高了。只看平均值，你永远发现不了问题。

3.4 实战：从日志里揪出内存泄漏

好，理论说完了，咱们来点实战。假设你看到这样的GC日志模式：

2024-01-15T10:30:00.000+0800: 0.000: [GC (Allocation Failure) ... 512M->480M(1024M), 0.05 secs]
2024-01-15T10:30:05.000+0800: 5.000: [GC (Allocation Failure) ... 512M->480M(1024M), 0.05 secs]
2024-01-15T10:30:10.000+0800: 10.000: [GC (Allocation Failure) ... 512M->480M(1024M), 0.05 secs]
...
2024-01-15T10:35:00.000+0800: 300.000: [Full GC (Allocation Failure) ... 1024M->900M(1024M), 1.5 secs]
2024-01-15T10:35:05.000+0800: 305.000: [Full GC (Allocation Failure) ... 1024M->950M(1024M), 1.8 secs]

这个模式太经典了。我一眼就能看出问题：

Minor GC之后，堆内存从512M降到480M，只回收了32M。说明大部分对象都存活下来了。
这些存活对象不断晋升到老年代，老年代很快就满了。
然后Full GC开始频繁出现，而且每次回收后内存还在涨（900M→950M）。

这就是典型的内存泄漏特征。对象只增不减，GC回收不掉。遇到这种情况，我建议你：

先dump堆内存，用MAT或者JProfiler分析。
看哪个对象占用了最多内存，查它的GC Root链。
十有八九是某个集合类（HashMap、ArrayList）无限增长，或者ThreadLocal没清理。

记住这个规律：如果每次GC后，老年代占用都比上一次高，那就是内存泄漏。如果每次GC后老年代占用稳定在一个值，那是内存不够用，加堆就行。

好了，GC日志解读这块，核心就是这些。你只要记住：看格式、分类型、算停顿、找趋势。下次再遇到线上GC问题，别慌，先翻日志。日志不会骗你，它会告诉你一切。

📚 课程目录