5.4 GC 日志判读：从滚动输出里读出病情

5.4 GC 日志判读：从滚动输出里读出病情

本节摘要：GC 日志是收集器的体检报告：统一日志开关打开后，每次回收的原因、各代变化、停顿耗时全部在案。本节以 G1 与 ZGC 的真实日志为标本逐字段解读，归纳"正常波动"与"病灶信号"的边界，并用泄漏与晋升暴风两条病案演示完整判读流程。

前三节建立了"正常 GC 长什么样"的心象，本节练临床读片。线上排错的顺序通常是反的：先看到日志异常，再倒推机制。所以判读的目标不是欣赏日志格式，而是回答三个问题——用的什么收集器、回收是否健康、下一步该查什么。所有示例基于 JDK 11 之后的统一日志（-Xlog:gc），JDK 8 的老式格式结构相同，字段名略有出入。

打开日志的正确姿势

统一日志的开关粒度从粗到细，生产环境推荐从第一条开始：

# 生产常用：基本回收信息，带时间戳与进程启动相对时间
-Xlog:gc:file=gc.log:time,uptime,level,tags:filecount=5,filesize=20m

# 排错加细：回收后各代明细（相当于老版 PrintGCDetails）
-Xlog:gc*:file=gc.log:time,uptime,level,tags
​

前三章的实验里已经零散见过日志行，现在正式给一段 G1 回收日志逐字段注解：

[12.087s][info][gc] GC(35) Pause Young (Normal) (G1 Evacuation Pause)
[12.087s][info][gc] GC(35)   Eden regions: 512->0(512)
[12.087s][info][gc] GC(35)   Survivor regions: 32->30(64)
[12.087s][info][gc] GC(35)   Old regions: 118->120
[12.087s][info][gc] GC(35)   Archive regions: 2->2
[12.087s][info][gc] GC(35) Pause Young (Normal) (G1 Evacuation Pause)
                     672M->244M(1024M) 18.423ms
​

逐行读：十二点零八七秒是进程启动后的时刻，GC(35) 是回收序号；Pause Young 说明是年轻回收，括号里是触发原因（G1 Evacuation Pause 即分区搬运回收，Allocation Failure 最常见）；中间各行为回收前后各逻辑代占用的 Region 数；末行是整堆变化 672M 降到 244M（总容量 1024M）与停顿 18.423 毫秒。一次健康年轻回收的画像：Eden 清零、Survivor 微调、Old 略涨、整堆明显回落、停顿在目标内。

判定健康的核心等式只有一条：回收应当有净收益——这次回收腾出的空间，应当明显大于两次回收之间的新增量；停顿应当稳定在收集器目标量级。偏离这条等式，就有病灶。

两条病案的完整判读

病案一：慢性泄漏。某服务每十分钟一次年轻回收很规律，但把整堆数字拉长时间轴看，每次回收后的"谷底"在缓慢抬升：

GC(120) ... 612M->288M(1024M) 16.9ms
GC(160) ... 688M->352M(1024M) 17.4ms
GC(205) ... 744M->421M(1024M) 18.0ms
GC(258) ... 810M->503M(1024M) 19.1ms
​

谷底 288、352、421、503——单调上涨。这是教科书级的泄漏曲线：每轮都有活对象晋升进老年代再也不下来，年轻回收的"净收益"逐次缩水，直到某天谷底逼近堆顶，Full GC 登场。判读到这一步，处置顺序就明确了：先用 jmap 抓堆直方图对比两次回收的类实例数（第六章 6.3 有完整手法），锁定"只进不出"的那类对象，再回头查持有链。日志只负责报警与定位节奏，最后一步靠直方图定凶器。

病案二：晋升暴风。另一种典型曲线是年轻回收频率突然翻倍、Survivor 与 Old 同步猛涨、单次停顿明显拉长：

GC(301) Pause Young (Normal) (G1 Evacuation Pause) 690M->260M(1024M) 18.1ms
GC(302) Pause Young (Normal) (G1 Evacuation Pause) 692M->262M(1024M) 18.6ms
GC(303) Pause Young (Normal) (G1 Evacuation Pause) 694M->263M(1024M) 19.0ms
GC(304) Pause Young (Mixed) (G1 Evacuation Pause) 700M->300M(1024M) 31.7ms
​

回收间隔从十分钟缩到几分钟，且回收后的谷底几乎不动（260 到 263）——意味着新分配的量大到"刚清完就满"。这不是泄漏（谷底没涨），是分配速率异常：某段代码开始批量制造中生命期对象（缓存失效回源、批量查询一次载入全表、序列化大报文），对象熬过一轮回收进入 Survivor 甚至老年代，Mixed 回收被拖出来善后（302 行后的 Pause Mixed 与 31.7 毫秒停顿是信号）。处置方向不是调 GC 参数，而是顺着"分配速率突增"找业务变更——这也是第六章 6.3 病灶二的标准起点。

ZGC 日志的长相

ZGC 的日志结构不同，判读要点也不同：

[2024-03-02T10:15:22.181+0000] GC(57) Garbage Collection (Warmup) 1024M(25%)->384M(9%)
[2024-03-02T10:15:22.188+0000] GC(57) Pause Mark Start 0.019ms
[2024-03-02T10:15:22.196+0000] GC(57) Pause Mark End 0.021ms
[2024-03-02T10:15:22.205+0000] GC(57) Pause Relocate Start 0.018ms
​

三轮极短停顿（各二十微秒量级）构不成感知，主体标记与搬运都在后台并发完成。判读 ZGC 时重点看的不是"停顿多少"（几乎必然达标），而是并发周期的吞吐：Complete 标签后的各阶段耗时、以及"Allocation Stall"字样——出现它说明业务线程等内存分配等急了，通常是堆给小了，ZGC 的处方是加内存而不是调参。

⚠️ 常见坑：只盯单次停顿数字。单次停顿正常不代表健康——泄漏病案里每次停顿都不大，病在趋势。判读必须看时间序列：回收频率、谷底水位、净收益三条曲线一起看，单一指标会骗人。

⚠️ 常见坑：生产开 gc* 全量日志不管容量。明细日志量可观，不加滚动与上限，磁盘被日志写满本身就是事故。上面的 filecount 与 filesize 参数就是为此准备的。

💡 关键直觉：GC 日志的读法是"看三条曲线，不背字段"——回收频率、回收后谷底、单次净收益。频率升、谷底涨是泄漏；频率升、谷底平是分配风暴；频率平、停顿涨多半是堆在变大或碎片在恶化。三条曲线一组合，病因范围立刻收窄到两种以内。

要点回顾

• 统一日志开关：-Xlog:gc 起步，排错用 gc*，生产务必配滚动与容量上限；
• 字段骨架：时刻、序号、类型与原因、各代前后变化、整堆净变化、停顿时长；
• 健康等式：净收益明显、停顿稳定在目标量级——偏离即病灶；
• 泄漏曲线：回收后谷底单调抬升，年轻回收收益逐次缩水，终点是 Full GC；
• 分配风暴曲线：回收频率陡增而谷底平稳，Mixed 回救场、停顿拉长，去查业务分配速率；
• ZGC 判读重点：三轮微停顿不代表一切，盯并发周期耗时与 Allocation Stall。

GC 章收官：判定、清运、家族、读片四块拼图齐全。下一章从"机器自己保养"转向"人给机器体检"——jstat、jmap、jstack、jcmd 四件套怎么用，内存之外的病灶（锁竞争、CPU 飙升）怎么定位，参数处方怎么开。