多彩编程 多彩编程MZPH · CODE BLOG
ARTICLE DETAIL

文章详情

深耕前端与后端开发技术的一线实战笔记与踩坑复盘。

JVM Full GC频繁导致接口超时?一次完整的调优实战复盘

JVM Full GC频繁导致接口超时?一次完整的调优实战复盘 那是一个典型得不能再典型的周四下午。我刚准备合上电脑去茶水间接水监控大屏上一条告警弹了出来某核心服务的FGCFull GC频率突然从每几小时一次变成了每两分钟一次接口平均响应时间从50ms飙到了1200msTP99更是直接突破了3秒。群里已经有业务同事开始刷屏问“服务是不是挂了”。我深吸一口气拉开终端开始了一次持续将近两个小时的JVM调优实战。这篇文章就是那一次调优的完整复盘。我会把当时每一步的判断逻辑、用到的命令、改过的参数、以及为什么这么改的原因全部写出来而不是只贴一串参数让读者去抄。无论你是初级开发还是已经写过几年Java只要需要排查线上性能问题这篇记录里的思路应该都能派上用场。1. 故障初现一个诡异的性能瓶颈1.1 现象接口突然变慢应用频繁卡顿先说现象。这个服务是一个典型的中间层应用负责从上游拉取数据做一番清洗、聚合之后再提供给下游的多个业务方调用。平时流量不算爆炸每秒几百次请求的量级核心接口的P999延迟一直控制在200ms以内。但告警出现的时候整个服务的表现非常反常接口平均响应时间从50ms左右直接跳到1200ms以上单机QPS从400左右掉到不足80但CPU使用率并没有打满只有不到30%GC日志里频繁出现Full GC单次暂停时间在1到3秒之间应用日志里开始出现大量的连接池获取超时这里有一个很关键的判断点可能很多同学第一次遇到会搞混这个现象的本质是服务变慢了但CPU却没跑满说明应用线程的时间并没有花在“干活”上而是大概率花在了等待和暂停上。我当时的第一反应就是看GC但为了严谨我还是先把线程栈抓了因为也有可能是锁竞争或者外部依赖阻塞。1.2 第一波排查先把“现场”抓牢排查线上问题最重要的一件事是先保留现场再动手分析。我顺手做了这几件事用jstack连续抓了几份线程栈用jstat -gcutil查看了实时的GC状态用top -H -p查看了CPU和线程的真实消耗情况把GC日志单独摘了出来果然jstat的输出很有说服力Eden区几乎一直是满的S0和S1区的使用率反复在95%以上跳动而老年代的使用率每隔几分钟就会触发一次Full GC的阈值。与此同时线程栈的结果显示大量业务线程都阻塞在内存分配上没有发现死锁也没有出现大量线程卡在外部IO上的情况。到这里方向已经基本锁定整个服务被频繁的GC暂停拖垮了。接下来要做的事情就是搞清楚为什么GC会变得这么频繁。提示排查JVM问题尽量先抓线程栈和GC日志。线程栈能帮你排除锁竞争和外部依赖问题GC日志能帮你判断内存分配和回收的节奏。两样都拿到手再决定下一步往哪边深入。2. 定位根因GC日志里藏着的真相2.1 看懂GC日志里的关键指标先把当时GC日志里最有代表性的几行摘出来[GC (Allocation Failure) [PSYoungGen: 310681K-49137K(339968K)] 310681K-215899K(1033216K), 0.0817307 secs] [Full GC (Ergonomics) [PSYoungGen: 49455K-0K(339968K)] [ParOldGen: 663901K-685017K(693120K)] 713356K-685017K(1033216K), [Metaspace: 46852K-46852K(1089536K)], 1.8722910 secs]这里需要解释几个概念很多新手看到这堆数字就容易晕。第一行是Young GC第二行是Full GC。方括号里的内容是年轻代的回收情况后面跟着的是整个堆的回收情况。比如第一行310681K-49137K(339968K)表示年轻代区域从310MB降到49MB区域总大小是339MB。后续的310681K-215899K(1033216K)表示整个堆从310MB降到215MB堆总大小是1033MB。第二行的Full GC (Ergonomics)注意这个Ergonomics字样意思是“自适应调整”。这个关键词特别重要它表明JVM认为当前的使用率触发了某种阈值主动进行了一次全局的Full GC。后面的1.87 secs说明这次暂停花了将近2秒。我又往前翻了翻历史日志发现Full GC发生的频率大概是每隔100到200次Young GC就会出现一次这背后就是非常典型的内存分配压力过大的问题。2.2 为什么Full GC频繁发生这里必须把“GC为什么频繁”这个问题从头到尾讲透不然调优就是瞎调。JVM的堆内存分为年轻代和老年代年轻代又分为Eden区、S0区和S1区。正常情况下绝大多数对象先在Eden区分配经过几次Minor GC之后如果还存活会被晋升到老年代。Minor GC因为只回收年轻代通常很快Full GC则要回收整个老年代甚至会伴随年轻代的回收速度慢得多。当我们看到老年代使用率在Full GC之前已经达到660MB以上而老年代总大小只有693MB这意味着老年代的可用空间已经不足30MB。这时候只要再有稍微大一点的对象晋升过来就会直接触发Full GC。Full GC过后老年代仅仅从685MB降到685MB基本等于“没降”说明这些对象全是存活对象根本回收不掉。现在问题变成了为什么会有这么多对象晋升到老年代第一应用代码里可能存在一批生命周期比较长的缓存对象或者没有及时清空的集合。第二年轻代空间设置得可能不够大导致一批对象还没来得及在年轻代里被回收就因为Minor GC被“挤”到了老年代。第三可能存在大量在代码里直接创建的大对象大对象会直接进入老年代。我结合代码分析发现这个服务里确实有一个内部的内存缓存保存了一批字典类的中间结果大约占了200MB左右。这部分对象长期存活属于正常现象但问题在于它把老年代的大部分空间都吃掉了留给真正的“可回收对象”的空间就变得很少了。此外年轻代的总大小只有340MB其中Eden区大约272MB、两个Survivor区各34MB。每次Young GC之后仍然存活的对象会被搬到Survivor区如果Survivor装不下就要提前晋升到老年代。从这个配置看Survivor区确实小了点而且服务在请求高峰期创建新对象的速度非常快Eden区很快就满Minor GC的间隔时间短一批对象在几次GC之间根本来不及熬到被回收的时机就被晋升了。注意对象晋升老年代不一定是“老”了才晋升。很多时候是因为Survivor空间不够或超过了MaxTenuringThreshold这会让原本可以死在年轻代的对象被迫住进老年代。老年代一旦满了Full GC就像多米诺骨牌一样跟着来。2.3 聊聊自动调整策略和GC选择当时的JVM参数里没有特别指定垃圾收集器所以默认使用了JDK 8下针对并行场景的ParallelGC线上跑的是JDK 8默认垃圾收集器就是Parallel Scavenge Parallel Old。这套组合的特点是注重吞吐量会通过Ergonomics自动调整年轻代的大小和晋升阈值。在大多数场景下ParallelGC没问题但一旦出现高分配速率和频繁晋升它的自适应逻辑反而会帮倒忙。将来如果重部署新版本我会推荐直接考虑JDK 17平台配合G1或ZGC。但在当次排查中因为JDK版本没法随便换只能在现有版本下把堆大小和参数调优。搞清楚问题根源之后调优的方向就很明确了给老年代腾出更多空间让年轻代更合理尽量降低晋升率。请看下一节的实操记录。3. 调优实战参数怎么改依据是什么3.1 先看机器配置再定堆大小调参之前我先看了机器配置。应用部署在一台4核8GB内存的容器上操作系统和JVM自身以及其他基础进程都要占用一些内存。关于堆大小业界常见的建议是容器内存的50%到70%留给堆具体看业务的实际情况。当时这台机器上还部署了一个日志采集的Agent和一些监控工具大概会额外占500MB左右。综合考虑后我决定把堆从原有的1GB扩展到4GB。这里有一笔账值得算一下。8GB总内存扣掉操作系统和基础进程占用约1.5GB再扣掉堆外常用的Direct Memory、线程栈、Metaspace等约1GB剩下的可分配空间大约在5GB左右。保守起见直接给堆分配4GB也就是-Xms4g和-Xmx4g设为一样。这里有一个常见的疑问为什么不把堆调得更大比如5GB或6GB因为堆外还需要留足空间如果堆太大反而会导致Metaspace或者直接内存出现压力甚至触发操作系统级别的Swap那种情况会比GC频繁更难受。我在这台4核的机器上还确认了一个比较重要的点JVM进程的堆大小直接决定了GC的停顿时间堆越大单次Full GC的暂停时间就会越长。当时1GB堆的Full GC已经能到1.8秒如果直接把堆调到6GB恐怕单次暂停会变成3到4秒更不可控。因此4GB是一个兼顾容量和暂停的平衡点。3.2 调整年轻代和晋升阈值堆的总大小定了接下来要细化年轻代的比例。原有配置里年轻代大约340MB占堆的1/3。为啥不直接沿用这个比例因为这个服务的对象分配速率太高年轻代太小对象会频繁晋升到老年代。在总堆4GB的前提下我把年轻代设为大约1.5GB占比37.5%左右比原来的33%略高但幅度克制。为了更精准我使用显示参数覆盖自适应的年轻代大小-Xmn1536m。这里明确出来虽然会导致Young GC单次扫描的空间变大、间隔变长但它给新对象提供了更充足的缓冲空间能让大量对象在Eden区直接死亡避免了晋级到老年代。然后是晋升阈值。原来ParallelGC默认的MaxTenuringThreshold是15但实际晋升往往达不到15次就因为Survivor空间满而提前晋升。我特意把目标晋升次数调高意义不大因为在Survivor空间不足时一样会提前晋升所以我主要通过扩大Survivor区的相对比例来间接解决。最终我通过同时指定-XX:SurvivorRatio8让Eden和Survivor区的大小比例是8:1:1即Eden约1.2GB、S0和S1各约153MB。S区从原来的34MB一下增加到153MB能容纳更多的晋升对象给年轻代对象更长的缓冲时间。调整后的整体尺寸结构是堆总量4GB年轻代1.5GBEden 1.2GBS0/S1各153MB老年代2.5GB老年代2.5GB相比原来的693MB可用空间几乎翻了接近4倍。在各种业务数据全量载入缓存之后老年代使用率大约在1.8GB左右仍然有0.7GB的富余空间既给了Full GC拖延的余地又避免堆碎片堆积过密导致频繁FGC。这里要插一句很多文章会说老年代占比越大FGC就越少理论上是这样但也不是越大越好。因为老年代过大意味着年轻代偏小会导致Minor GC更加频繁而每次Minor GC都在复制存活对象如果存活率不低这部分拷贝开销反而会成为新的性能瓶颈。年轻代和老年代的比例要根据对象分配速率、存活周期和晋升率来综合权衡不能拍脑袋。3.3 从Parallel换成G1还是继续用CMS当时面对的一个路线选择是要不要把垃圾收集器从Parallel换成CMS或者G1先说CMS。CMS在JDK 8里已经是一个比较成熟的选择它的特点是并发标记和并发清除能显著减少Full GC时的停顿时间。但CMS也有一个大坑就是碎片化问题。CMS无法做堆内存的整理久而久之老年代碎片化严重会触发Concurrent Mode Failure然后退化成Serial Old的单线程Full GC那将是一场灾难。而且CMS在JDK 9之后就被标记为废弃了在新版本上不可用从长远看是死路。G1是另一个选择。G1的设计目标是可预测的暂停时间它把堆分成很多Region通过维护一个优先队列来优先回收垃圾最多的Region。在4GB堆、4核CPU这个配置上G1完全可以支撑。但是G1在JDK 8上毕竟还不是特别成熟当时网上关于G1在JDK 8的不稳定案例也不少另外我们还有个数据缓存导致大量存活对象的特殊情况G1的Mixed GC量级并不小如果TAMS标记变量设置不合理同样会产生明显的停顿。对比之下我在那次调优中选择了保留ParallelGC这是因为ParallelGC最大的优势是吞吐量高在这个场景下只要老年代空间够用FGC频率降下来整个服务的性能就已经回到正常了。关键问题不是收集器不够强而是内存布局不合理。后来我也想通了调优的第一原则是“先解决主要矛盾不盲目升级组件”。如果换收集器之后仍然问题复现会多出一个排查维度反而增加复杂度。如果你当前的项目跑的是JDK 11及以上我建议优先选G1配一个-XX:MaxGCPauseMillis100的目标停顿时间再结合-XX:G1NewSizePercent和-XX:G1MaxNewSizePercent控制年轻代大小。但千万记住G1不是银弹它对大对象的分配处理不如ParallelGC方式直接如果大对象过多也需要单独调优。3.4 最终的参数配置和前后效果对比那次调优最终落地到配置里的关键参数如下-Xms4g -Xmx4g -Xmn1536m -XX:SurvivorRatio8 -XX:UseParallelGC -XX:UseParallelOldGC -XX:MetaspaceSize256m -XX:MaxMetaspaceSize512m -XX:HeapDumpOnOutOfMemoryError -XX:HeapDumpPath/data/logs/jvm/ -XX:PrintGCDetails -XX:PrintGCDateStamps -Xloggc:/data/logs/jvm/gc-%t.log这里逐项说明一下-Xms4g -Xmx4g初始堆和最大堆都设为4GB避免运行时堆扩容带来的性能抖动。-Xmn1536m固定年轻代为1.5GB年轻代老年代保持合理比例。-XX:SurvivorRatio8Eden:S0:S1 8:1:1S区有充足的晋升缓冲。-XX:UseParallelGC -XX:UseParallelOldGC显式指定并行收集器避免未来JDK升级后默认收集器变化导致的不确定性。-XX:MetaspaceSize256m -XX:MaxMetaspaceSize512m设定了Metaspace初始大小避免动态扩容导致Full GC。-XX:HeapDumpOnOutOfMemoryError和-XX:HeapDumpPath内存溢出时自动导出堆转储方便事后分析。开启GC日志并输出到文件日志文件名带上时间戳方便按天归档分析。上线调整之后我盯着监控数据看了一个多小时对比效果非常明显指标调优前调优后Full GC频率每2分钟一次每8小时左右一次Full GC平均暂停1.8秒约200毫秒Young GC频率每秒数次每10秒左右一次接口平均RT1200ms60msTP99 RT大于3秒150ms单机QPS80480客观说调优后的Full GC并没有完全消失这是正常的因为那个200MB的缓存对象毕竟还占着老年代的空间只要业务有缓存刷新或者某批对象集中晋升依然会触发FGC。但频率从“分钟级”降到“小时级”停顿时间也大幅缩短这已经足以让服务稳定扛住高峰流量了。注意JVM调优的目标不是“零GC”而是让GC的频率和耗时都控制在业务可接受的范围内。一个永远不Full GC的Java应用是不存在的如果有人告诉你他把FGC调没了那大概率是在撒谎或者堆小到溢出了。4. 避坑指南JVM调优里的那些细节4.1 参数不是越多越好小步快跑才是王道这次调优过程中我克制住了“一次把所有参数全改了”的冲动。这里想特别提醒读者JVM参数之间存在联动效应。如果你同时调大了堆、改了年轻代比例、换了一个收集器又设置了多个阈值一旦性能回升你也说不清到底是哪个参数起的作用假如性能变差排查难度更是成倍增长。我建议的执行策略是一次只改一组有强关联的参数比如这轮的改进重点就是“堆大小和年轻代结构”那就只动这一组参数上完成后观察至少30分钟到1小时最好能覆盖一个完整的业务高峰周期。如果效果不达标再进入下一轮调整。我见过很多团队把网上某个“最佳配置”直接贴到生产环境三天后出问题又回滚始终没搞明白问题出在哪个参数上。另外有个容易踩的低级坑-Xmx和-Xms如果不一致JVM在运行初期会不断扩容和缩容堆这个过程本身就会触发暂停。所以如果你预期堆大小基本恒定直接将两者设置为一个值省掉动态调整的负担。4.2 用JFR和Heap Dump做更精细的定位GC日志只是第一层信息。如果调完参数后FGC频率依然异常或者你想知道到底是什么对象占据了老年代就不能只靠GC日志了。我当时为了验证缓存对象占用补充了一次Heap Dump分析。这里分享一下基本流程使用jmap -dump:live,formatb,fileheap.hprof手动导出一份堆快照。如果进程已经无法响应就依赖于启动参数里的-XX:HeapDumpOnOutOfMemoryError自动导出。用MATMemory Analyzer打开快照查看Dominator Tree和Leak Suspects报告。当时的结果很清楚有一个HashMap结构的缓存实例占用了将近600MB其中的key和value都是业务字典对象另外还有一批遗留的无效List对象占了几十MB。JFR则更适合日常问题追踪。只要在JDK 11环境里用-XX:StartFlightRecording参数开启低开销的持续记录就能拿到分配采样、锁竞争、IO等待、GC暂停等所有关键数据。如果你还在使用JDK 8也可以使用商业版本的JMC配合降级使用不过现在主流选择还是直接升级到长期支持版本省心得多。有一种情况特别适合用到JFR当GC频率已经恢复正常但接口RT依然偏高时就需要通过JFR的线程分析去看是否有锁竞争或Hot Method热点。GC日志只会告诉你垃圾回收花了多久不会告诉你业务线程在哪里等锁、等IO。GC只是JVM性能问题的一个维度不是全部。4.3 几组实用排查命令速查在这里把排查过程中用到的关键命令整理一份速查表命令行工具并不臃肿好记好查命令作用使用场景jstat -gcutil pid 1000每秒输出一次GC各区域的使用率快速判断Eden、Survivor、Old是否异常jstack pid thread.txt导出线程栈确认是否存在阻塞、死锁或大量RUNNABLE卡在分配jmap -heap pid查看堆的详细配置和当前使用情况对比实际堆参数与启动参数是否一致jmap -dump:live,formatb,filea.hprof pid导出存活对象堆转储分析大对象和内存泄漏top -H -p pid查看进程内的线程CPU占用定位高CPU线程配合jstack转换nidjcmd pid GC.class_histogram输出类实例数量占用快速统计占用最高的类有个排查技巧top -H输出的线程号是十进制的而jstack输出的线程号是十六进制的。使用时需要先转换比如线程TID是12345转成十六进制就是0x3039。这个问题我见过不止一个同事卡住了每次都要提醒。4.4 JVM调优的常见误区汇总另外把这次调优过程中想到的几个常见误区一并写在这里这些坑我几乎都见过别人踩过误区一堆设置越大越好。堆太大GC暂停时间会线性变长内存溢出风险也会更高。堆大小和行为之间是一条曲线绝不是单调递增的收益。误区二自定义参数使ParallelGC的AdaptiveSizePolicy失效就不可取。确实当手动指定-Xmn、-XX:SurvivorRatio后JVM的自适应调整就不再介入年轻代大小。但这不代表错因为自动调整的前提是基于默认的目标某些场景下手动指定会更可控。重点是你要知道自己做了这个选择。误区三看GC日志只盯Full GC。Minor GC如果是够快但频繁一样会大量消耗CPU从而使吞吐量下降。当时调优后Young GC频率降了一个数量级整体CPU占用和业务RT都好了不少这部分收益不能忽略。误区四调优一次就能一劳永逸。业务流量、数据规模、代码变更都会影响对象的生命周期分布调优应该是一个持续监控和迭代的过程。每次大版本迭代之后最好重新审视一下GC日志和堆使用情况。5. 最后再聊几点实在的心得那次调优结束之后我给服务配置了常规的GC监控告警不只是看Full GC次数还把Full GC导致的暂停时间也加了阈值告警。后来一段时间里每次业务大促前我都会把GC日志拉出来看一眼判断一下是否需要对堆参数做微调。有人可能会问为什么不直接把代码里的缓存优化一下那样从源头上减少内存占用岂不是更好答案是后续确实做了代码层面的优化比如给缓存加了过期清理机制把无效的List对象改成了复用对象。但当时线上正在报警直接改代码要经过代码评审、测试、发布时间窗口太长。而JVM参数调整可以在不改变代码行为的前提下立刻缓解问题属于最高优先级的止血操作。等线上稳定了再慢慢推进代码优化这才是正确的顺序。另外有一个小细节值得每个Java开发者记住线上排查时拿到问题的第一件事不是搜索答案而是先看一眼现状。GC日志、线程栈、堆配置、监控图表这四个基本数据尽量在五分钟之内拿到然后基于数据做决策。不要靠猜不要凭感觉。JVM调优本质上是一件讲证据的事情你拿到的信息越充分走的弯路就越少。这份实战记录写到这儿就差不多了。如果你也遇到了类似Full GC频繁、RT突增的问题希望这套从现象定位到参数调整再到效果验证的流程能帮你少踩几个坑。如果调完之后问题依然存在别急着继续加参数把Heap Dump和线程栈好好分析一遍往往真正的答案就藏在那一堆对象里。
返回列表