【JVM原理详解】30-GC日志解读与调优实战

30-GC 日志解读与调优实战前面几篇分别讲了各款收集器的原理和参数但真正的调优能力来自看懂 GC 日志 定位问题 验证效果的闭环。本篇是垃圾回收模块的收官篇我们用真实案例串起日志格式、分析工具、调优方法最后给出生产环境参数推荐。读完这篇你应该能独立完成一次完整的 GC 调优。GC 日志格式JDK 8 vs JDK 9JDK 8 的传统日志JDK 8 用-XX:PrintGCDetails打印 GC 详情格式是自由文本java-XX:PrintGCDetails-XX:PrintGCDateStamps-XX:PrintGCTimeStamps\-Xloggc:gc.log-cpMyApp com.example.Main输出示例2016-07-20T11:53:04.0530800: 1.234: [GC (Allocation Failure) [PSYoungGen: 262144K-30720K(305664K)] 424960K-204800K(983040K), 0.0234567 secs] [Times: user0.05 sys0.01, real0.02 secs] 2016-07-20T11:53:05.6780800: 2.345: [Full GC (Ergonomics) [PSYoungGen: 30720K-0K(305664K)] [ParOldGen: 174080K-163840K(677376K)] 204800K-163840K(983040K), [Metaspace: 25600K-25600K(1073152K)], 0.2345678 secs] [Times: user0.80 sys0.01, real0.23 secs]关键字段GC (Allocation Failure)触发原因Allocation Failure 分配失败Eden 满。PSYoungGen新生代名PS 表示 Parallel Scavenge。262144K-30720K(305664K)回收前→回收后当前总大小。424960K-204800K(983040K)全堆 回收前→回收后堆总大小。0.0234567 secs本次 GC 停顿时间。[Times: user0.05 sys0.01, real0.02 secs]用户态、内核态、实际墙钟时间。user远大于real说明多线程并行user 各线程 CPU 时间之和。JDK 9 的统一日志XlogJDK 9 引入统一日志框架JEP 158用-Xlog:统一管理所有日志GC 日志格式结构化、可解析java-Xlog:gc*info:filegc.log:time,uptime,level,tags\-cpMyApp com.example.Main参数拆解-Xlog:what:output:decorators:level what gc*info所有 GC 相关日志info 级别 output filegc.log输出到文件 decorators time,uptime,level,tags日志前缀格式输出示例[2026-07-17T10:00:01.2340800][1.234s][info][gc,start ] GC(0) Pause Young (Allocation Failure) [2026-07-17T10:00:01.2340800][1.234s][info][gc,heap ] GC(0) PSYoungGen 262144K-30720K(305664K) [2026-07-17T10:00:01.2340800][1.234s][info][gc ] GC(0) Pause Young (Allocation Failure) 424960K-204800K(983040K) 0.0234567s [2026-07-17T10:00:01.2340800][1.234s][info][gc,cpu ] GC(0) User0.05s Sys0.01s Real0.02s改进点结构化每行有 tag如[gc,heap]便于工具解析。统一格式所有收集器用同一套日志框架不再各写各的。可过滤-Xlog:gc*info控制粒度debug 级可看更多细节。常用 Xlog 配置# 基础生产推荐-Xlog:gc*info:filegc.log:time,uptime,level,tags# 详细调试用-Xlog:gc*debug:filegc.log:time,uptime,level,tags# 堆详情含每次 GC 后区域占用-Xlog:gc*info,gcheapdebug:filegc.log:time,uptime,level,tags# 同时输出到控制台和文件-Xlog:gc*info:filegc.log:time,uptime,level,tags:gc*info:stdout:time,level,tagsYoung GC 日志解读以 G1 的 Young GC 为例[1.234s][info][gc,start] GC(0) Pause Young (Normal) (G1 Evacuation Pause) [1.234s][info][gc,task] GC(0) Using 8 workers [1.234s][info][gc,heap] GC(0) Eden regions: 80-0(80) [1.234s][info][gc,heap] GC(0) Survivor regions: 0-8(8) [1.234s][info][gc,heap] GC(0) Old regions: 0-0 [1.234s][info][gc,heap] GC(0) Humongous regions: 2-2 [1.234s][info][gc] GC(0) Pause Young (Normal) 500M-200M(2048M) 5.678ms [1.234s][info][gc,cpu] GC(0) User0.04s Sys0.01s Real0.005s逐行解读GC(0)第 0 次 GC计数从 0 开始。Pause Young (Normal)Young GCNormal 表示常规触发非 Mixed。G1 Evacuation PauseG1 的复制式回收。Using 8 workers8 个 GC 线程。Eden regions: 80-0(80)Eden 从 80 个 Region 清空到 0共 80 个。Survivor regions: 0-8(8)Survivor 从 0 涨到 8 个。500M-200M(2048M)堆占用从 500M 降到 200M总堆 2048M。5.678ms本次停顿。User0.04s Sys0.01s Real0.005sUser Real 说明多线程并行8 线程 × 5ms ≈ 40ms user time。健康指标回收量500M → 200M回收了 300M有效率 60%。停顿5.678ms对 G1 来说很健康。频率看相邻两次 GC 的时间间隔结合业务负载判断。Full GC 日志解读Full GC 通常是异常信号要重点分析[10.234s][info][gc,start] GC(15) Pause Full (G1 Compaction Pause) [10.234s][info][gc,phases] GC(15) Phase 1: Mark live objects [10.235s][info][gc,phases] GC(15) Phase 2: Prepare compaction [10.236s][info][gc,phases] GC(15) Phase 3: Adjust pointers [10.240s][info][gc,phases] GC(15) Phase 4: Compact heap [10.241s][info][gc,heap] GC(15) Old regions: 200-50 [10.241s][info][gc] GC(15) Pause Full (G1 Compaction Pause) 1800M-600M(2048M) 6.789msG1 的 Full GC 分四阶段JDK 10 多线程并行Mark live objects标记存活对象。Prepare compaction计算整理后的对象位置。Adjust pointers调整所有指向移动对象的引用。Compact heap实际搬运对象整理碎片。本次 Full GC触发原因G1 Compaction Pause通常是 Mixed GC 跟不上或碎片严重。回收效果1800M → 600M回收 1200M碎片整理释放。停顿6.789ms——G1 并行 Full GC 比 CMS 的 Serial Old 快得多但仍应避免。触发原因分类Allocation Failure ── 新生代分配失败常规 Young GC Ergonomics ── JVM 自适应决定自适应触发 System.gc() ── 代码显式调用应避免 G1 Compaction Pause ── G1 退化的 Full GC调优目标 CMS Mode failure ── CMS 降级 Serial OldJDK 8 Metadata GC Threshold── Metaspace 不足触发类加载多看到System.gc()要查代码是否调用了System.gc()或用-XX:DisableExplicitGC禁用。在线分析工具GCEasyGCEasygceasy.io是最流行的在线 GC 日志分析工具。使用流程采集日志用-Xlog:gc*info:filegc.log输出到文件。上传访问 gceasy.io上传 gc.log。分析报告工具返回可视化报告。关键指标GCEasy 报告的核心指标Throughput吞吐量应用运行时间占比目标 95%。Avg GC Pause平均停顿所有 GC 的平均停顿。Max GC Pause最大停顿最差情况关注 P99。Young GC / Full GC 次数Full GC 应极少甚至为 0。内存 reclaimed每次 GC 回收的内存量。健康判断标准指标健康警告危险吞吐量 95%90-95% 90%平均停顿 50ms50-200ms 200ms最大停顿 200ms200-1000ms 1sFull GC 频率0偶发频繁Young GC 间隔稳定波动趋势下降其他工具GCViewer本地 Java 工具离线分析适合内网环境。JDK Mission ControlJMCJDK 11 自带关联 GC 事件与应用行为。VisualVM可视化监控含 GC 插件。Prometheus Grafana生产监控通过 JMX Exporter 采集 GC 指标。调优案例案例1新生代太小导致频繁 Young GC现象某电商订单服务JDK 11 G1堆 4GB。监控显示 Young GC 每分钟 20 次平均停顿 8msP99 延迟 120ms业务敏感。日志[10:00:01.000] GC(100) Pause Young 800M-600M(4096M) 7.8ms [10:00:03.500] GC(101) Pause Young 820M-610M(4096M) 8.1ms [10:00:06.000] GC(102) Pause Young 800M-600M(4096M) 7.5ms诊断每次 GC 间隔仅 2.5 秒说明 Eden 很快填满。日志显示Eden regions: 30-0(30)Region 8MBEden 总共 240MB——太小了。默认G1NewSizePercent520%下限被压低了。调优# 扩大新生代下限给 Eden 更多空间-XX:G1NewSizePercent30-XX:G1MaxNewSizePercent50效果Eden 涨到 1.2GBYoung GC 间隔延到 8 秒次数降 70%吞吐量从 92% 到 97%。教训G1 自适应有时会把新生代压太小为达成停顿目标。对延迟敏感场景用G1NewSizePercent设下限。案例2内存泄漏导致频繁 Full GC现象某金融系统JDK 8 CMS堆 8GB。运行 3 天后开始频繁 Full GC每次 3-5 秒服务卡顿。日志[Day1] 老年代回收后 2GB [Day2] 老年代回收后 4GB [Day3] 老年代回收后 6GB → Concurrent Mode Failure → Full GC Serial Old老年代回收后占用持续上升——典型的内存泄漏信号。正常情况下 GC 后老年代应该稳定在某个水位。诊断在 Full GC 频发时触发堆 dumpjcmdpidGC.heap_dump /tmp/heapdump.hprof用MATMemory Analyzer Tool打开 dump。看 “Dominator Tree” 找最大对象。发现ConcurrentHashMap占 5GBkey 是String内容是会话 ID——会话结束未清理。调优修复代码会话结束时map.remove(sessionId)。临时缓解加-XX:ExplicitGCInvokesConcurrent让System.gc()走并发路径。效果修复后老年代稳定在 1.5GBFull GC 消失。教训GC 后老年代持续上升 内存泄漏。用 MAT 分析 heap dump 是定位的标准流程。案例3G1 调优降低停顿现象某直播弹幕服务JDK 11 G1堆 16GB。MaxGCPauseMillis 默认 200ms但实测 P99 停顿 450ms长尾请求超时。日志分析[gc] GC(50) Pause Young 4000M-2000M(16384M) 180ms ← OK [gc] GC(55) Pause Young (Mixed) 8000M-5000M(16384M) 320ms ← 超标 [gc] GC(60) Pause Young (Mixed) 9000M-5500M(16384M) 480ms ← 严重超标Mixed GC 停顿长——因为 CSet 太大回收太多 Old Region。调优# 降低停顿目标-XX:MaxGCPauseMillis100# Mixed GC 分更多次每次少回收-XX:G1MixedGCCountTarget16# 提早启动并发标记避免 Mixed GC 堆积-XX:InitiatingHeapOccupancyPercent35# 限制 Mixed GC 回收的 Old Region 比例-XX:G1OldCSetRegionThresholdPercent5效果MaxGCPauseMillis 从 450ms 降到 120ms。Mixed GC 次数增加但每次停顿可控。P99 延迟达标吞吐量略降98% → 97%可接受。教训G1 的停顿目标需要和 CSet 大小配合。降停顿 减小 CSet 增加回收频率。这是停顿 vs 频率的权衡。生产环境参数推荐通用 Web 服务JDK 11/17G1java-Xms4g-Xmx4g\-XX:UseG1GC\-XX:MaxGCPauseMillis200\-XX:InitiatingHeapOccupancyPercent45\-XX:G1HeapRegionSize8m\-XX:G1NewSizePercent20\-XX:G1MaxNewSizePercent50\-XX:G1MixedGCCountTarget8\-XX:ExplicitGCInvokesConcurrent\-XX:ParallelRefProcEnabled\-XX:UseContainerSupport\-XX:MaxRAMPercentage75\-Xlog:gc*info:file/var/log/gc.log:time,uptime,level,tags:filecount5,filesize20m\-XX:HeapDumpOnOutOfMemoryError\-XX:HeapDumpPath/var/log/heapdump\-cpMyApp com.example.Main低延迟服务JDK 17ZGCjava-Xms8g-Xmx8g\-XX:UseZGC\-XX:MaxGCPauseMillis10\-XX:UseContainerSupport\-XX:MaxRAMPercentage75\-Xlog:gc*info:file/var/log/gc.log:time,uptime,level,tags:filecount5,filesize20m\-XX:HeapDumpOnOutOfMemoryError\-XX:HeapDumpPath/var/log/heapdump\-cpMyApp com.example.Main批处理JDK 11/17Paralleljava-Xms8g-Xmx8g\-XX:UseParallelGC\-XX:GCTimeRatio19\-XX:MaxGCPauseMillis500\-XX:UseContainerSupport\-XX:MaxRAMPercentage80\-Xlog:gc*info:file/var/log/gc.log:time,uptime,level,tags\-cpMyApp com.example.BatchJob日志滚动配置# 文件滚动5 个文件每个 20MB-Xlog:gc*info:file/var/log/gc.log:time,uptime,level,tags:filecount5,filesize20m防止日志撑满磁盘保留最近 100MB 日志够用于事后分析。实践要点1. 日志必开生产环境必须开 GC 日志开销极低 1% CPU。没日志的 GC 问题等于盲调事倍功半。2. 建立基线调优前先采集 24 小时正常 GC 日志用 GCEasy 分析记录吞吐量、停顿分布作为基线。任何调优都要和基线对比避免感觉变好的自欺欺人。3. 一次只改一个参数# 错误一次改 5 个参数-XX:MaxGCPauseMillis100-XX:G1MixedGCCountTarget16\-XX:InitiatingHeapOccupancyPercent35-XX:G1NewSizePercent30\-XX:G1OldCSetRegionThresholdPercent5改多个无法判断哪个有效。一次改一个验证后再改下一个。4. 压测验证调优后必须用生产级负载压测验证。开发环境空载下 GC 表现好不代表生产也行。推荐 JMeter / Gatling 模拟真实流量。5. 监控 Full GCFull GC 次数是红线指标。正常情况下应为 0一旦出现立即告警。生产中用 Prometheus 监控jvm_gc_pause_seconds_max并设告警阈值。6. 容器内存限制# 必须设避免 JVM 误用宿主机内存-XX:UseContainerSupport-XX:MaxRAMPercentage75JDK 10 默认开启容器感知但仍需设MaxRAMPercentage限制堆占容器内存比例留 25% 给堆外内存Metaspace、线程栈、Direct Buffer。7. OOM 自动 dump-XX:HeapDumpOnOutOfMemoryError-XX:HeapDumpPath/var/log/heapdumpOOM 时自动生成 heap dump事后用 MAT 分析。生产事故的黑匣子。小结GC 日志格式JDK 8 用-XX:PrintGCDetails自由文本JDK 9 用-Xlog:gc*info结构化统一日志后者更易解析和过滤。日志解读要点看触发原因、回收前后内存、停顿时间、User/Real 比值判断并行度Full GC 日志要重点分析触发原因和各阶段耗时。分析工具GCEasy在线、GCViewer本地、JMCJDK 11 自带、Prometheus生产监控。调优案例(1) 新生代太小→扩大 Eden(2) 内存泄漏→MAT 分析 heap dump(3) G1 停顿超标→减小 CSet、增加 Mixed GC 次数。生产参数推荐Web 服务用 G1 200ms 停顿目标低延迟用 ZGCJDK 17批处理用 Parallel。必开 GC 日志滚动、OOM dump、容器内存限制。调优方法论建基线 → 一次改一参 → 压测验证 → 对比指标形成闭环。至此垃圾回收模块从如何判定对象存活到各款收集器原理再到日志解读与调优实战已完整闭环。GC 调优没有银弹理解原理 看懂日志 科学验证才是稳定可靠的调优之道。更多内容JVM调优实战