4. 启动过程剖析
GC 日志这东西，说实话，很多同学一开始都觉得头疼。满屏的英文缩写、数字、时间戳，看着就像天书。但我可以负责任地告诉你——GC 日志是 JVM 性能调优的「黑匣子」。飞机失事要找黑匣子，JVM 出问题，第一件事就是翻 GC 日志。
我个人习惯是，线上环境必须开启 GC 日志。哪怕你暂时不看，也得开着。为什么？因为问题往往发生在你睡觉的时候，等你第二天上班，现场早就没了。日志就是你的时间机器。
启动参数怎么配？
先别急着分析，你得先把日志打开。我常用的三板斧是这样的：
-Xloggc:/path/to/gc-%t.log
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-XX:+UseGCLogFileRotation
-XX:NumberOfGCLogFiles=10
-XX:GCLogFileSize=10M这里我解释一下每个参数的作用：
| 参数 | 作用 | 我的建议 |
|---|---|---|
-Xloggc |
指定 GC 日志输出路径 | 用 %t 加时间戳，避免覆盖 |
-XX:+PrintGCDetails |
输出详细的 GC 信息 | 必开，否则日志太简略 |
-XX:+PrintGCDateStamps |
打印人类可读的时间戳 | 比相对时间好用太多 |
-XX:+UseGCLogFileRotation |
启用日志轮转 | 防止日志撑爆磁盘 |
-XX:NumberOfGCLogFiles |
保留的日志文件数 | 10 个够用，多了占空间 |
-XX:GCLogFileSize |
单个日志文件大小 | 10M 一个，方便传输和分析 |
-Xlog:gc* 的格式。如果你用的是 JDK 11+，记得用新语法。我曾经在升级 JDK 时忘了改参数，结果日志没打出来，排查问题多花了半天。
GC 日志长什么样？
好，参数配好了，我们来抓一条真实的 GC 日志看看。这是我从一个线上服务截取的：
2024-03-15T10:32:18.456+0800: 2.345: [GC (Allocation Failure) [PSYoungGen: 51200K->8192K(59392K)] 102400K->60192K(196608K), 0.0123456 secs] [Times: user=0.02 sys=0.01, real=0.01 secs]嗯，乍一看确实有点乱。但别怕，我们把它拆开来看，其实就几个部分：
- 时间戳：
2024-03-15T10:32:18.456+0800—— 这是PrintGCDateStamps带来的好处，精确到毫秒。 - JVM 启动后时间：
2.345—— 表示 JVM 启动后 2.345 秒发生了这次 GC。 - GC 类型和原因：
GC (Allocation Failure)—— 这次是 Minor GC，原因是分配失败（说白了就是 Eden 区满了）。 - 年轻代信息：
[PSYoungGen: 51200K->8192K(59392K)]—— 年轻代从 50MB 回收到了 8MB，总容量约 58MB。 - 堆整体信息：
102400K->60192K(196608K)—— 整个堆从 100MB 降到了 58.8MB，总容量 192MB。 - 耗时：
0.0123456 secs—— 12 毫秒，很快。 - CPU 时间：
[Times: user=0.02 sys=0.01, real=0.01 secs]—— 用户态 20ms，内核态 10ms，实际耗时 10ms。
核心要点：看 GC 日志，我一般先看三个数字——回收前、回收后、总容量。回收前如果接近总容量，说明内存快满了；回收后如果还是很大，说明有对象没释放掉，可能是内存泄漏。
Full GC 日志长什么样？
Minor GC 看完了，咱们再看看 Full GC。这个才是真正让人头疼的：
2024-03-15T10:35:42.123+0800: 186.234: [Full GC (Metadata GC Threshold) [PSYoungGen: 8192K->0K(59392K)] [ParOldGen: 131072K->139264K(139264K)] 139264K->139264K(196608K), [Metaspace: 99876K->99876K(1048576K)], 0.5678901 secs] [Times: user=0.89 sys=0.12, real=0.57 secs]这个日志比刚才那个长了不少。为什么？因为 Full GC 涉及了所有区域。我来拆解一下：
- 触发原因：
Metadata GC Threshold—— 元空间（Metaspace）达到了阈值。我在项目中遇到过好几次，都是因为动态生成类太多导致的。 - 年轻代：
PSYoungGen: 8192K->0K(59392K)—— 回收后变 0 了，说明年轻代被清空了。 - 老年代：
ParOldGen: 131072K->139264K(139264K)—— 等等，回收后反而变大了？从 128MB 涨到了 136MB？ - 堆整体：
139264K->139264K(196608K)—— 回收前后一模一样，136MB 纹丝不动。 - 耗时：
0.5678901 secs—— 568 毫秒，这已经算比较慢了。
注意这个细节：老年代回收后反而变大，说明年轻代的对象被晋升到了老年代。如果这种情况频繁发生，你的 Survivor 区可能太小了，或者晋升阈值设置不合理。我曾经在一个高并发服务上遇到过，Survivor 区只有 2MB，结果对象刚创建就被晋升到老年代，Full GC 频繁触发，服务响应时间直接飙到 5 秒以上。
如何快速定位问题？
日志读懂了，接下来就是怎么用。我总结了一个「三步排查法」：
- 看频率：Minor GC 多久一次？Full GC 多久一次？如果 Full GC 每小时超过 1 次，就要警惕了。
- 看耗时：单次 GC 耗时多少？Minor GC 超过 100ms 算慢，Full GC 超过 1s 算严重。
- 看趋势：老年代占用是平稳的，还是持续上涨的？持续上涨基本就是内存泄漏。
举个例子，我去年排查过一个线上问题。GC 日志显示：
2024-06-01T00:00:00.000+0800: 12345.678: [Full GC 1024M->1024M(2048M), 2.345 secs]
2024-06-01T00:05:00.000+0800: 12350.678: [Full GC 1024M->1024M(2048M), 2.456 secs]
2024-06-01T00:10:00.000+0800: 12355.678: [Full GC 1024M->1024M(2048M), 2.567 secs]看到了吗？每 5 分钟一次 Full GC，每次耗时 2 秒多，而且回收前后堆大小完全不变。这说明什么？堆里的对象全是存活的，一个都回收不掉。这就是典型的内存泄漏。后来通过 heap dump 分析，发现是一个缓存 Map 没有设置过期策略，越积越多。
我的小技巧：如果你不想手动翻日志，可以用 grep 配合 awk 快速统计。比如：grep "Full GC" gc.log | wc -l 可以统计 Full GC 次数。更专业的可以用 GCeasy、GCViewer 这些工具，能自动生成图表。
一张图看懂 GC 日志分析流程
说了这么多，我画了一张流程图，把整个分析思路串起来：
常见问题速查表
最后，我整理了一个速查表。你在分析日志时，可以直接对照：
| 日志现象 | 可能原因 | 我的建议 |
|---|---|---|
| Minor GC 频繁（每秒多次） | Eden 区太小 | 增大年轻代大小，或调整 -XX:NewRatio |
| Minor GC 耗时超过 100ms | GC 线程竞争或对象太多 | 检查 -XX:ParallelGCThreads 设置 |
| Full GC 频繁（每小时多次） | 老年代增长过快 | 检查是否有大对象直接进入老年代 |
| Full GC 后老年代占用不变 | 内存泄漏 | 立即 dump 堆，分析引用链 |
| 元空间 Full GC | 动态类加载过多 | 增大 -XX:MaxMetaspaceSize，或检查类加载器泄漏 |
GC 日志中出现 System.gc() |
代码中显式调用了 System.gc() |
加上 -XX:+DisableExplicitGC 禁用 |
最后说一句：GC 日志分析不是一次性工作。我建议你养成习惯，每次上线新版本后，都盯一下 GC 日志看 15 分钟。很多问题在灰度阶段就能发现，等全量上线再查就晚了。