外观
GC 日志解读
GC 日志是唯一能事后还原 JVM 行为的东西。看得懂它,OOM 和 CPU 高这两类问题就有一半能提前发现。
一、开启(两套语法)
JDK 9+ 统一日志框架:
bash
-Xlog:gc*:file=/var/log/app/gc.log:time,uptime,level,tags:filecount=5,filesize=50mJDK 8:
bash
-XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCApplicationStoppedTime \
-Xloggc:/var/log/app/gc.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=50M两套语法不能混用
JDK 11 上写 -XX:+PrintGCDetails 会直接启动失败:Unrecognized VM option。反过来 JDK 8 不认 -Xlog:。迁移时这是最常见的第一个报错。
二、G1 日志逐行拆解
text
[2026-10-27T16:31:22.418+0800][184221.338s] GC(1842) Pause Young (Normal) (G1 Evacuation Pause)
[2026-10-27T16:31:22.418+0800][184221.338s] GC(1842) Using 8 workers of 8 for evacuation
[2026-10-27T16:31:22.461+0800][184221.381s] GC(1842) Eden: 1024.0M(1280.0M)->0.0B(1216.0M) Survivors: 64.0M->128.0M Heap: 3482.6M(4096.0M)->2512.4M(4096.0M)
[2026-10-27T16:31:22.461+0800][184221.381s] GC(1842) Pause Young (Normal) 1280M->2512M 43.117ms| 字段 | 含义 | 关注点 |
|---|---|---|
GC(1842) | 第 1842 次 GC | 序号连续,可对齐业务日志时间轴 |
Pause Young (Normal) | 年轻代停顿 | 括号里 Concurrent Start 表示顺带启动了并发标记 |
G1 Evacuation Pause | 触发原因 | 见下方"原因对照表" |
Eden: 1024M(1280M)->0B(1216M) | 回收前(容量)→回收后(新容量) | Eden 没清空 = 有问题 |
Heap: 3482M(4096M)->2512M(4096M) | 整堆变化 | 回收后的值持续上涨就是泄漏 |
43.117ms | 本次 STW 时长 | 与 MaxGCPauseMillis 对比 |
解释 (A)->(B) 这个格式:箭头左边是回收后实际使用量,括号里是回收后 JVM 调整的新容量。1024.0M(1280.0M)->0.0B(1216.0M) 读作"Eden 从 1024M(总容量 1280M)清到 0,并把 Eden 目标容量调成 1216M"。
三、Full GC 的日志长什么样
text
GC(1877) Pause Full (G1 Compaction Pause)
GC(1877) Phase 1: Mark live objects 1243.881ms
GC(1877) Phase 2: Compute new object addresses 188.204ms
GC(1877) Phase 3: Move objects 942.117ms
GC(1877) Pause Full (G1 Compaction Pause) 4021.332ms解释:Full GC 是单线程式的压缩整理,4 秒全停顿。G1 出现 Full GC 基本意味着两件事之一:
- 晋升失败(to-space exhausted):并发标记跟不上分配速度
- 大对象(Humongous)分配失败:单个对象超过 region 一半
对应的危险日志:
text
GC(1876) Pause Young (Concurrent Start) ... to-space exhausted
GC(1876) GC caused by humongous allocation failure看到 to-space exhausted 就该扩容或调 -XX:G1HeapRegionSize、-XX:InitiatingHeapOccupancyPercent,而不是等它变 Full GC。
四、触发原因对照表
| 日志里的原因 | 含义 | 通常怎么办 |
|---|---|---|
G1 Evacuation Pause | Eden 满了,正常回收 | 无需处理 |
Concurrent Mark / Pause Initial Mark | 并发标记周期的开始/结束 | 关注整个周期耗时 |
to-space exhausted | 没有空 region 可放存活对象 | 增大堆 / 调低 IHOP / 减少分配速率 |
G1 Humongous Allocation | 大对象直接分配 | 查代码里的大数组/大 List,或调大 region |
Metadata GC Threshold | 元空间到阈值 | 查类泄漏,或加 MaxMetaspaceSize |
Last ditch collection | 元空间快爆了做的挣扎 | 同上,且已经很紧急 |
System.gc() | 代码或 NIO 显式触发 | 加 -XX:+DisableExplicitGC 或 -XX:+ExplicitGCInvokesConcurrent |
Allocation Failure | Parallel/CMS 时代的分配失败 | 正常,看频率 |
五、几个必须会算的指标
bash
# 平均单次 Young GC 停顿
awk '/Pause Young/ {for(i=1;i<=NF;i++) if($i ~ /ms$/){gsub(/ms/,"",$i); s+=$i; n++}} END{printf "avg %.1fms over %d pauses\n", s/n, n}' gc.log
# 每分钟 GC 次数与总耗时
grep -oE '^\[2026-[0-9-]+T[0-9]{2}:[0-9]{2}' gc.log | sort | uniq -c | sort -rn | head
# 回收后堆使用量的趋势(判断泄漏)
grep -oE 'Heap: [0-9.]+M\([0-9.]+M\)->[0-9.]+M' gc.log | awk -F'->' '{print $2}' | tail -20| 指标 | 健康线 | 超了说明 |
|---|---|---|
| Young GC 平均耗时 | < 50ms | 对象太大或存活率高,复制成本上升 |
| Young GC 频率 | 每几秒一次算正常 | 太频繁 → Eden 太小或分配速率太高 |
| Full GC 频率 | 几小时/几天一次可接受 | 每分钟一次必须处理 |
| Full GC 后堆占用 | 明显下降 | 不降 → 内存泄漏 |
| GC 时间占比 | < 5% | 超了就是"GC 风暴" |
六、常用调优参数(按目的记)
bash
-XX:MaxGCPauseMillis=200 # 停顿目标,G1 靠它自动调 region 和并发线程
-XX:InitiatingHeapOccupancyPercent=45 # 老年代占堆多少就启动并发标记(默认 45)
-XX:G1HeapRegionSize=16m # region 大小,大对象多就调大
-XX:G1NewSizePercent=20 -XX:G1MaxNewSizePercent=60 # 年轻代占比下限/上限
-XX:+ParallelRefProcEnabled # 并行处理引用,引用多时显著降停顿
-XX:+DisableExplicitGC # 屏蔽 System.gc()解释:调 G1 的原则是先给目标(MaxGCPauseMillis),别急着定死分代大小。手动设 -Xmn 会让 G1 的自适应失效,是常见的"越调越糟"起点。
七、工具
| 工具 | 用途 |
|---|---|
| GCEasy(gceasy.io 上传 gc.log) | 自动生成报告:停顿分布、吞吐率、问题诊断 |
| GCViewer | 本地离线画图,看停顿与堆趋势 |
jstat -gcutil pid 1000 | 实时趋势,不需要日志 |
Arthas dashboard | 实时分区占用 |
先开日志再上线
GC 日志的代价是 1~2% 吞吐,但没有它,事后所有内存问题都是猜。建议所有 Java 服务默认开启并配轮转,磁盘留 250M 足够(5 × 50M)。