那阵子我们线上有个支付渠道服务晚上高峰期总是时不时冒出几个超时报警。CPU不高、内存看着也没满就是接口偶尔卡一下每次卡个几百毫秒到一秒不等。排查了很久没头绪最后把GC日志翻出来才发现每两三分钟就有一个Full GCOld区回收完还是占了80%以上。顺着GC日志往里挖定位到某个缓存对象在循环里被反复拼接成大数组修掉之后整个服务安静得让人不适应。从那以后我养成了一个习惯不管线上出什么问题先把GC日志抓到手里。GC日志就是JVM的黑匣子它不会告诉你业务为什么慢但它能告诉你内存里正在发生什么回收器在替你扛什么。这篇文章就把我平时做GC日志分析的一套方法完整写出来从怎么开日志、怎么看日志到怎么透过日志判断问题再到常见故障怎么定位争取让看完的人能直接拿去用。1. 为什么我把GC日志当作JVM的“黑匣子”很多做Java开发的人对GC日志的态度是知道有这个东西但从来不看。应用能跑就行报错了再打日志慢了就加内存实在不行重启一下。这种操作方式在小项目里确实能撑一阵子但一旦流量上来GC日志往往是第一个告诉你危险的信号。GC日志记录的是JVM进行垃圾回收时的行为包括什么时候回收、回收了哪些区域、回收前花了多少内存、回收后剩多少、停顿了多久、是Minor GC还是Full GC。这些信息可以直接回答几个很要命的问题系统变慢是因为GC停顿还是业务代码本身就慢内存是不是在悄悄增长最后拖垮整个JVMEden区是不是频繁被打满导致Minor GC过于频繁Old区为什么一直在涨对象是怎么晋升上去的这些问题在应用日志里几乎找不到答案但在GC日志里都有明确记录。准确说GC日志是目前观察JVM堆内运行情况最直接、最可靠的入口没有之一。什么时候需要重点看GC日志我的经验是这三类场景必须看接口RT抖动但业务日志里没有明显异常代码走查也看不出问题服务莫名其妙频繁Full GC或者时不时出现OutOfMemoryError上线新功能或调整JVM参数后想确认内存模型和回收行为是否符合预期。说白了GC日志不是出了问题才翻的工具它应该成为Java服务上线前的标配观测项。我见过太多线上事故其实早在大规模宕机之前GC日志里已经连续出现异常趋势了只是没人去读。2. 不同JDK版本的GC日志开启方式从PrintGCDetails到统一日志GC日志怎么开首先要看你用的JDK版本。不同版本之间的参数差异很大这个坑如果不注意线上很容易配了没效果或者配完日志文件疯狂膨胀把磁盘打满。2.1 JDK 8及之前的传统参数JDK 8是当前存量系统里最常见的一个版本配套的GC日志参数是传统风格-Xloggc:/data/logs/gc.log -XX:PrintGCDetails -XX:PrintGCDateStamps -XX:PrintGCTimeStamps这几个参数各管一摊事-Xloggc指定GC日志输出到文件路径要确保存在且应用有写权限-XX:PrintGCDetails输出每次GC的详细内存变化这是分析的核心数据-XX:PrintGCDateStamps在每条日志前加上绝对日期时间方便跟业务日志对照-XX:PrintGCTimeStamps加上JVM启动以来的相对秒数用来计算GC发生的时间间隔。如果还想看对象晋升和存活年龄的分布可以追加-XX:PrintTenuringDistribution这个参数会打印各年龄对象的大小分布对分析“对象过早晋升”这类问题很有用。另外有一个参数我建议非特殊情况不要开就是-XX:PrintHeapAtGC它会在每次GC前后把整个堆的详细输出打一遍信息量虽然大但日志体量会爆炸对排障来说通常没必要。JDK 8还有一个很容易被忽略的多余参数-XX:PrintGC。很多人以为开它就够了但它只输出最简略的一行根本没有细节对分析帮助不大。既然用了-XX:PrintGCDetails就不需要再写-XX:PrintGC了。2.2 JDK 9及之后的统一日志进入JDK 9之后JEP 158把JVM日志做成了统一框架老参数虽然还兼容但会报警告新项目的正确做法是使用-Xlog-Xlog:gc*:file/data/logs/gc.log:time,uptime,level,tags这段的意思是输出所有带gc标签的日志到文件时间格式包含系统时间和JVM启动秒数同时显示日志级别和标签。注意gc*的星号不能省它代表匹配gc以及gc下面的子标签比如gcheap、gcage、gcergo这样细分的类别。如果只想看GC暂停和堆变化可以简化成-Xlog:gc:file/data/logs/gc.log:time,uptime但做分析最好还是用gc*不然很多有用的子标签信息看不到。需要特别注意JDK 9的-Xlog参数位置有讲究它和普通-XX参数不一样不能随便放在-jar命令的后面。正确用法是放在java命令和-jar之间。我之前见过有人把它当成普通JVM参数追加到最后结果Java进程直接报错无法启动。2.3 日志滚动配置别让GC日志把磁盘写爆GC日志如果不做滚动运行时间长了之后文件会非常大轻则占满磁盘重则拖垮整个应用。JDK 8老参数阵营里滚动靠两个参数-XX:UseGCLogFileRotation -XX:NumberOfGCLogFiles5 -XX:GCLogFileSize20MJDK 9的-Xlog可以配合文件大小和数量参数比如-Xlog:gc*:file/data/logs/gc.log:time,uptime,level,tags:filecount5,filesize20m我习惯按5个文件、每个20MB来配置既能覆盖突发高峰期几天的日志又不至于占太多磁盘。对GC日志来说没必要追求存太久它最重要的作用是出事的时候能往前回溯一段够用就行。生产环境改完这些参数必须重启才能生效因为GC日志开关是在JVM启动时确定的。有些中间件支持通过JMX动态调一部分参数但GC日志开关这块我不建议依赖动态方案稳妥做法是发布时把参数固化到启动脚本里并且配置完看一眼生成的日志文件确认确实在写。3. 拆解一行GC日志回收前后到底发生了什么日志开了之后一堆格式各异的文本出现了。很多人第一步就卡在这里看不懂。其实GC日志的格式是高度结构化的拆开来看并不复杂。关键是你得知道自己用的是哪个垃圾回收器不同回收器打出来的内容长得很不一样。3.1 传统回收器Serial/Parallel/CMS的日志格式以Parallel Scavenge为例一个典型的Minor GC长这样2019-04-11T15:02:32.4520800: 745.482: [GC (Allocation Failure) [PSYoungGen: 261120K-26112K(304640K)], 0.0323159 secs] [Times: user0.06 sys0.00, real0.03 secs]逐个字段拆2019-04-11T15:02:32.4520800绝对时间来自PrintGCDateStamps745.482JVM启动后经过的秒数来自PrintGCTimeStampsGC表示这是Minor GC。如果这里是Full GC就是整堆回收Allocation Failure触发原因意思是Eden区分配新对象失败这是最常见的Minor GC触发原因PSYoungGen回收的区域这里是Parallel Scavenge的年轻代261120K-26112K(304640K)回收前占用261120K、回收后占用26112K、该区域总容量304640K0.0323159 secs本次GC耗时这个值对应第一次停顿时间[Times: user0.06 sys0.00, real0.03 secs]CPU时间user、sys和实际墙钟时间real。user大于real说明GC使用了多线程并行回收。再看Full GC2019-04-11T15:02:33.4310800: 746.461: [Full GC (Metadata GC Threshold) [PSYoungGen: 26112K-0K(304640K)] [ParOldGen: 700026K-682381K(700240K)] 726138K-682381K(1004880K), [Metaspace: 20361K-20361K(1069056K)], 0.0876950 secs] [Times: user0.08 sys0.00, real0.09 secs]这里能看到年轻代和老年代分别的变化然后是整堆的变化726138K-682381K(1004880K)以及Metaspace的变化。Full GC的原因Metadata GC Threshold代表元空间达到了阈值触发回收这个问题后面会重点讲。3.2 G1回收器的日志格式JDK 8之后默认回收器逐渐切换到G1G1的日志格式比传统回收器多了一个分阶段信息2025-01-10T10:00:00.1230800: 125.123: [GC pause (G1 Evacuation Pause) (young) [Parallel Time: 20.0 ms, GC Workers: 8] [Eden: 1024.0M(1024.0M)-0.0B(1024.0M) Survivors: 16.0M-16.0M Heap: 2048.0M(4096.0M)-1986.0M(4096.0M)] [Times: user0.05 sys0.02, real0.01 secs]首先看GC pause (G1 Evacuation Pause) (young)。G1的回收活动叫“暂停”可以是young年轻代或mixed年轻代老年代。Parallel Time是并行回收阶段的总耗时如果这个值大说明单次GC时间很长。堆变化那行是重点Eden: 1024.0M(1024.0M)-0.0B(1024.0M)表示Eden区从1024M清到0Survivor区从16M变16M整个Heap从2048M降到1986M。G1的容量单位可能是K或M这个要看具体版本和配置。还要留意G1日志里的Humongous相关字样。G1把超过Region大小50%的对象称为“巨型对象”分配巨型对象有时候会直接触发一次GC比如[Humongous Register: 5.0M] [Humongous Reclaim: 0.2M]如果日志里频繁出现Humongous基本可以断定代码里在频繁创建大对象这是个重要信号。3.3 JDK 9统一格式的日志怎么读JDK 9的输出经过了重新整理比老版本干净很多[0.345s][info][gc] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 23M-1M(63M) 2.013ms [0.345s][info][gc,cpu] GC(0) User0.00s Sys0.00s Real0.00sGC(0)是GC序号方便日志里搜索某一GC。后面是类型、堆变化和耗时。相比JDK 8统一格式更紧凑但也少了部分细节。要看更细的内容可以加标签-Xlog:gcheapdebug:file/data/logs/gc.log:time,uptime,level,tags这样会输出每次GC前后的堆详细数据。日常分析和排查标准gc*级别就够了不用过度追求detail。4. 判断GC是否健康频率、停顿、内存趋势与吞吐量四个维度拿到一堆日志之后不能只看有没有关键字要从四个维度做整体评估。这四个维度是我日常分析的固定套路也是判断一套JVM参数配置是不是合理的核心标准。4.1 GC频率先看GC发生的频率。统计一下单位时间内Minor GC和Full GC各发生了多少次。怎么统计如果日志是JDK 8格式可以用grep加wc快速统计grep -c GC (Allocation Failure) gc.log grep -c Full GC gc.log然后结合日志覆盖的时间范围算出每分钟频率。正常情况下Minor GC可以频繁但一般以每几秒一次到每几十秒一次居多具体取决于Eden区大小和对象分配速率Full GC应该非常少很多健康服务甚至可以几天才一次如果一天好几次甚至一小时好几次那就必须介入如果Minor GC每秒都要来好几次说明新生代空间太小或者对象分配速率太高。频率是趋势指标单独看一次GC没意义一定要看一段时间的分布。4.2 GC停顿时间停顿时间是用户体验最直接的指标。每次GC都会有一段STWStop The World暂停所有业务线程的时间那段real0.03 secs就是停顿时长。判断标准我给一个经验值Minor GC停顿在几十毫秒内正常超过100ms就要关注Full GC停顿如果超过1秒线上基本会有可感知的抖动G1和ZGC的目标是控制停顿时间如果G1的real值经常超过200ms需要检查-XX:MaxGCPauseMillis设置和堆大小。读取停顿时间时要注意JDK 8日志里real不一定等于真正的暂停时间某些回收器在部分阶段是并发的real是整段GC日志的时间跨度。所以更严谨的方式是看回收器自己上报的停顿时间字段比如G1日志里的Pause Time。4.3 内存趋势这是我最看重的一个维度。GC日志里每一行都有“回收前-回收后总容量”把多个时间点的数据连起来就能画出堆内存使用趋势。核心看两点每次GC后堆剩余大小是否在缓慢爬升。如果Old区回收后占用率越来越高从50%到60%再到70%这是内存泄漏的典型信号GC频率是否随运行时间变得密集。如果昨天一天只有20次Full GC今天就到了50次明天到100次直线上升就是危险的信号。内存趋势分析不需要特别复杂的工具用脚本把Heap:或整堆变化的回收后数值提取出来按时间排序就能看出曲线。GCViewer工具也有这个功能后面章节会说。4.4 GC吞吐量吞吐量的定义是吞吐量 业务运行时间 / (业务运行时间 GC总耗时)计算方式很简单把一段时间内的GC耗时全部加起来然后用总时间减去GC耗时就是业务运行时间。举个例子一个服务运行了3600秒GC总耗时36秒那么GC开销占比是1%吞吐量是99%。业内一般建议GC开销控制在5%以内。如果超过这个值说明有大量CPU时间被GC消耗掉了表面上看业务代码很忙实际上都在帮回收器搬对象。这个指标可以透过工具自动算也可以简单用脚本统计grep -o real[0-9.]* secs gc.log | awk -F {sum$2} END {print sum}把real耗时全部加起来就是GC总耗时。接着除以日志时间跨度再换算成百分比。这四个维度不是孤立看的。频率高但停顿短和频率低但停顿长是完全不同的调优方向。前者要考虑扩容年轻代或降低对象分配后者要考虑换回收器或调整堆大小。只看单一维度很容易做出错误判断。5. 通过GC日志定位问题的实际案例从现象到根因的完整链路理论说完了接下来用几个真实的故障场景走一遍分析流程。这些场景都是我实际在项目里处理过或复盘过的虽然在具体数字上做了脱敏但思路完全一致。5.1 场景一Full GC频繁Old区回收后占比还是居高不下现象服务运行一两天后Full GC频率越来越高从每10分钟一次发展到每2分钟一次接口超时明显增加。GC日志里的关键特征[Full GC (Allocation Failure) [PSYoungGen: 0K-0K(304640K)] [ParOldGen: 689432K-682401K(700240K)] 689432K-682401K(1004880K), 0.0988760 secs]注意一个细节Young区回收前后都是0K说明已经没有对象在年轻代存活了。Old区回收前689M回收后682M几乎没降下去。整堆回收后仍然占到总容量的68%。这个数据说明老年代里存在大量无法被回收的对象而且这些对象占用的空间非常大。接下来就不会再看GC日志了而是把堆dump出来分析到底是哪些对象占了Old区。jmap -dump:formatb,fileheap.hprof pid然后用MAT或者VisualVM打开dump看支配树通常很快就能找到占大头的对象。我之前遇到过的情况是某个内存缓存Map没有清理机制Key一直累积导致Old区被撑爆。修复之后Full GC直接消失服务稳定运行了一个月GC日志里只有Minor GC。这类问题的判断逻辑很清晰Full GC后Old区回收效果差重点查堆不要浪费时间调参数。5.2 场景二Minor GC极其频繁但每次耗时很短现象应用整体响应还行但CPU占用偏高线程Dump里大量线程都在正常执行业务代码看不出阻塞。GC日志特征[GC (Allocation Failure) [PSYoungGen: 191744K-5184K(195328K)], 0.0089650 secs] [GC (Allocation Failure) [PSYoungGen: 192032K-6304K(195328K)], 0.0078860 secs] [GC (Allocation Failure) [PSYoungGen: 191936K-5472K(195328K)], 0.0090250 secs]三行GC都在几百毫秒内发生每次耗时不到10ms但抵不住频率高GC总CPU开销非常可观。这里的信息点在于Eden区总容量约192M回收前占用约191M也就是说Eden刚刚被填满就立刻触发回收。回收后Young区还剩5M左右说明大量短生命周期对象在Minor GC后就无法回收晋升到了Old区。这类问题通常是业务代码里创建了大量短期对象比如循环里做字符串拼接、JSON序列化、频繁创建临时集合。解法有两个方向一是改代码减少对象创建二是在不改代码的情况下调大年轻代提高Eden区容量降低Minor GC频率。如果决定调参可以设置-Xmn512m把新生代从默认比例调大配合观察GC频率曲线。但这不是长久之计根治还是要回到代码层面。5.3 场景三Metaspace触发Full GC现象服务运行一段固定时间后出现规律性的Full GC而且发生时间点高度一致。GC日志特征[Full GC (Metadata GC Threshold) [PSYoungGen: 8920K-0K(460800K)] [ParOldGen: 30205K-25618K(50176K)] 39125K-25618K(511976K), [Metaspace: 20480K-20480K(1069056K)], 0.0128450 secs]注意触发原因是Metadata GC Threshold而且Metaspace回收前后都是20480K没降下来。这说明元空间达到了触发阈值但类加载器本身并没有大量卸载Metaspace容量还在正常范围。这类情况在JDK 8比较常见因为MetaspaceSize默认值不大类加载到一定程度就触发Metaspace GC。处理方式是在启动参数里把MetaspaceSize设置到一个合理值让它不要过早触发回收。一般建议-XX:MetaspaceSize256m -XX:MaxMetaspaceSize512m具体值要看应用实际加载的类数量。设置之后观察GC日志这类Full GC通常会消失。注意不要为了省事把MaxMetaspaceSize设得过大真出现类加载器泄漏时反而会掩盖问题。5.4 场景四G1日志中频繁出现巨型对象现象使用G1回收器的服务在流量高峰期频繁出现GC暂停但堆整体占用并不高。GC日志特征[GC pause (G1 Evacuation Pause) (young) (initial-mark), 0.0359870 secs] [Humongous Register: 68.0M] [Eden: 512.0M(512.0M)-0.0B(512.0M) Survivors: 32.0M-32.0M Heap: 1024.0M(2048.0M)-956.0M(2048.0M)]Humongous Register显示这次GC注册了68M的巨型对象如果你知道G1的Region大小是1M那就意味着有大量超过0.5M的对象一直在被创建。巨型对象的分配在G1里成本很高而且因为无法在年轻代正常复制容易触发连续的GC。顺着这个线索查代码最后定位到某段逻辑会构造一个很大的二维数组高峰期并发一多就把G1逼得快疯了。改造方案是把大数组对象池化或者换成堆外存储改完之后Humongous Register基本上不再出现GC暂停也恢复到了20ms以内。5.5 场景五CMS的Concurrent Mode Failure这个场景在存量老系统里还很常见。GC日志出现过类似这样的内容[Full GC (Concurrent Mode Failure) ... 0.9769980 secs]Concurrent Mode Failure本质是CMS回收器在并发标记阶段老年代空间就被新对象填满导致CMS来不及完成并发回收被迫降级成Serial Old进行全停顿回收。停顿时间通常会超过1秒线上影响非常明显。根因通常是老年代容量设置偏小或者对象晋升速度过快。调整方向包括调大老年代空间比如-XX:OldSize、-Xmx提前触发CMS回收把-XX:CMSInitiatingOccupancyFraction从默认值调低比如68配合-XX:UseCMSInitiatingOccupancyOnly手动设定启动阈值如果条件允许直接迁移到G1或ZGC。碰到CMS问题别只盯参数还得看晋升速率。用-XX:PrintTenuringDistribution观察各年龄对象大小如果高龄对象占比异常往往意味着晋升阈值设置不合理。6. 分析工具怎么选GCViewer、GCeasy还有自己动手统计日志量大了之后纯靠肉眼一行行看肯定不现实。尤其是线上服务跑几天GC日志可能上万行。我日常会用工具做初步筛查再用脚本做定点分析。6.1 GCViewer本地离线分析首选GCViewer是一个开源的桌面工具可以直接把gc.log文件拖进去自动生成各种曲线图。它能直观展示堆使用随时间变化的曲线GC频率直方图每次GC的停顿时间分布吞吐量和GC开销的统计值。我个人用的版本是GitHub上的chewiebug/GCViewer一个jar包就能跑java -jar gcviewer.jar gc.log界面虽然朴素但信息密度非常高。尤其适合用来回答“整体趋势怎么样”这类问题。看一眼曲线如果发现每次GC后堆占用在稳步抬高基本可以判定内存泄漏方向不用再慢慢翻日志时间戳。GCViewer对JDK 8传统格式和G1格式支持得都不错但JDK 9统一格式的解析偶尔会有偏差它现在也支持由新型日志生成。如果发现数据不对还是拿原始文本验证。6.2 GCeasy网页版快速分享GCeasy是一个在线GC日志分析平台把日志文件传上去它能自动生成一份排版很友好的报告。适合不太想折腾本地工具的人也可以直接把报告链接发给同事一起看。使用时要特别注意数据安全。GC日志不包含业务数据但包含堆内存信息理论上存在一定泄露风险敏感项目不要用在线工具自己用GCViewer或者脚本分析更稳妥。6.3 自己动手写个简单统计脚本工具能给出图表但有些计算还是要自己来。比如把日志按小时分组统计GC次数或者统计某一段时间内停顿总时长写个小脚本比打开工具更快。JDK 8格式下可以用awk统计每次GC间隔awk /2019-04/{print $2} gc.log | awk -F: {print $1:$2} | uniq -c这条命令按小时统计GC日志条数能快速看出一天内哪个时段GC最频繁。如果要把停顿时间累加处理Times:字段grep -o real[0-9.]* gc.log | sed s/real// | awk {sum$1} END {print sum}这样就能算出日志覆盖时间内的总停顿秒数除以运行时长得到GC开销占比。很多看起来很高大上的监控数据其实用这几条命令就能算出来。6.4 辅助命令jstat做实时观察GC日志是事后分析如果想实时观察配合jstat看当前JVM的GC行为很有用jstat -gcutil pid 1000 10每秒打印一次各区域使用率和GC累计时间。jstat看到的是当前快照能够和GC日志相互印证。比如GC日志说Full GC频繁jstat里老年代使用率应该也居高不下两边对得上才能确认。实时监控体系完整的团队也可以接入Prometheus的JMX Exporter把GC次数和耗时指标可视化。不过GC日志依然是底层原始数据可视化指标出问题时最终还是要回来翻GC日志的细节。7. GC日志分析里最容易被忽略的几个细节文章最后把我在多次实战中踩过的坑和一些关键心得整理一下。GC日志必须结合业务流量看。同一套JVM参数白天高峰期和凌晨低峰期表现完全不同。分析时一定要先确认日志时间段对应的流量情况否则容易把正常的阶段性行为误判成故障。不要一看到Full GC就慌。Minor GC、Major GC、Full GC在日志里的含义和触发条件不同有些Full GC一共也就几十毫秒对业务没影响。真正危险的是停顿时间长、回收效果差的Full GC。调JVM参数要有“单变量原则”。一次只改一个参数改完跑一段时间再看GC日志。很多人一次调了五六个参数出了问题根本不知道是谁引起的。GC日志文件不要放在系统盘或数据盘根目录建议放在独立目录并做logrotate。GC日志虽然做了滚动但总容量依然在增长磁盘告警在关键时刻可能比GC本身更致命。使用G1时要理解它和传统回收器的调优思路完全不同。G1追求的是可预测的停顿时间堆越大Region越多调整-XX:MaxGCPauseMillis只影响它内部的行为目标不代表实际停顿一定能压到这个值。想真正稳定还是靠观察日志里的实际数据。遇到长时间无法定位的GC异常先想想最近上线了什么。多数GC问题的触发源在业务代码不在GC本身。一个线程池没关闭、一条大查询没分页、一个缓存没限流都可能让GC日志变得非常难看。调参数只是延缓症状找到根因才是治疗。我现在处理线上GC问题的固定流程是先对比告警时间段和GC日志确认是GC引起还是业务引起的然后按GC频率、停顿、内存趋势三个维度快速定位问题方向再看对应区域的详细数据判断是分配过多、晋升过快还是回收不动最后决定是客户端加参数还是提代码问题。整个流程走下来基本不超过半小时这套方法在多个项目里都验过希望对你也有用。