值班群里凌晨两点弹出一条告警订单服务调用价格计算接口超时率超过 0.5%。打开监控GC 时间曲线像锯齿一样剧烈跳动Full GC 今天已经发生了 37 次而且业务高峰还没到。这一眼注定这个月没法平静。那是一个电商营销中心的价格计算服务负责处理优惠券、满减、会员折扣这类规则计算大促前刚加过一批新的活动配置。从那天开始我们花了整整三周把每天 40 次的 Full GC 一步步压到 10 天才出现 1 次接口 p99 从 860ms 降到 210ms调用方超时率从 0.85% 降到 0.02%。这个月班加得值。很多团队遇到 Full GC 的第一反应是加内存但这次的问题恰恰说明堆大小只是表象真正的病灶在代码层面。这个复盘我整理了很久今天把它完整写出来从现象定位、根因分析、参数调优到配套监控给同样被 Full GC 折磨的兄弟们一份可以直接抄作业的排查思路。1. 问题来了线上服务一天 40 次 Full GC1.1 从一条告警说起告警规则其实很简单接口超时率连续 5 分钟超过 0.5% 就触发。价格计算服务平时很稳p99 稳定在 200ms 左右超时率常年不到 0.05%所以这条告警触发时值班的同学一度怀疑是上游下单服务出了问题。结果一查问题就在自己身上。监控上 GC 相关的指标全线飘红Full GC 次数当天累计 37 次单次最长停顿 3.2 秒Full GC 造成的 Stop-The-World 总时长已经超过了 70 秒。更麻烦的是这些 Full GC 几乎集中在晚上 8 点到 12 点的流量高峰段订单服务的重试请求又反过来加重了价格计算的负载形成了恶性循环。那会儿我还不知道根因是什么但有一件事很明确Full GC 是全局暂停的每次停顿时间里所有线程都在等接口自然超时。1.5 秒到 3 秒的停顿在平时可能只是偶发毛刺但在每秒处理几千个请求的高峰期全链路都会跟着抖。1.2 40 次 Full GC 到底意味着什么先给不太熟 JVM 的同事说清楚一个概念Full GC 和 Young GC 是两回事。Young GC 只清理年轻代速度快一般几十毫秒对业务影响小Full GC 要回收老年代还经常附带清理年轻代、元空间耗时动辄几秒而且整个过程应用线程全部暂停。像我们用的 JDK 8 默认组合下CMS 的 Full GC 是单线程 串行标记清理停顿更明显。每天 40 次 Full GC每次平均 1.8 秒意味着应用每天至少有 70 多秒是完全卡死的。这 70 多秒如果均匀分布还好问题是它总在请求最多的时候来运气不好的话一次 Full GC 正好落在核心接口调用链路上整条链路的超时、重试、熔断全都跟着遭殃。我还把 Full GC 的时间和接口超时曲线做了叠加对比两者的尖峰几乎完全重合。这一步很重要它让我们确认接口变慢的根因大概率就是 GC而不是代码逻辑、数据库或者依赖方的问题。排查方向一旦错了后面全是无用功。1.3 先别急着动参数建立排查基线很多同学一看到 Full GC 就先加 -Xmx或者把 CMSInitiatingOccupancyFraction 调大。我的建议是先忍着把该有的现场数据收集全再说。盲目调参最坑的地方在于你可能把 Full GC 从 40 次压到了 20 次但根因没解决过两天业务量一大又弹回来浪费了时间还误导了判断。我们当时先做了三件事。第一确认线上 GC 日志已经开启把-Xloggc:/opt/logs/gc.log -XX:PrintGCDetails -XX:PrintGCDateStamps这些参数补上没有日志后面全是盲猜。第二用 jstat 连续采样拿到当前堆的使用趋势。第三拉出最近一周的发布记录和配置变更先排除是不是某次上线带来的回归。这个基线阶段花了大半天但非常值。因为拿到数据之后问题的大致轮廓已经浮出来了老年代使用率在每次 Full GC 之后只能降到 75% 左右然后像爬坡一样慢慢往上涨大概一个多小时又触发一次 Full GC。这不是正常释放该有的曲线强烈指向有对象被长期持有、无法回收。2. 线索追踪从 GC 日志到堆转储2.1 GC 日志里第一眼看什么线上 GC 日志打开之后要看的信息其实就几类每次 GC 的原因、年轻代和老年代回收前后的占用、停顿时间、以及 Full GC 的时间分布。我们摘了一段有代表性的 Full GC 日志2024-12-02T21:15:33.4820800: 31245.678: [Full GC (Allocation Failure) [ParNew: 1048576K-1048576K(1048576K), 0.0000 secs] [CMS: 3584000K-2738580K(3495680K), 1.8532400 secs] 3942400K-3942400K(4019584K), [Metaspace: 189203K-189203K(1327104K)] [Times: user1.85 sys0.00, real1.85 secs]两个细节很扎眼。第一ParNew回收前后的容量一点没变说明年轻代已经被塞得满满的连晋升的通道都堵了。第二老年代从 3.5G 只降到了 2.7G降幅不到 25%这说明里面大量对象都是存活的、可达的CMS 标记完发现都是活对象自然清不动。这类日志多出现几次基本可以断定不是偶发分配而是有东西长期占着老年代。还有一点要提的是 Full GC 的触发原因。日志里写的是Allocation Failure意思是年轻代晋升对象时老年代已经没有足够连续空间了这在 CMS 下经常表现为并发模式失败或晋升失败。遇到这种情况光提高触发阈值CMSInitiatingOccupancyFraction治标不治本因为并发清理的速度赶不上对象增长的速度最后还是退化成 Full GC。2.2 jstat 判断老年代增长曲线光看日志还不够我习惯再用 jstat 实时采样几轮把堆的使用趋势画出来。命令很简单jstat -gcutil pid 1000 200每秒输出一次连续 200 次重点关注 O 那一列老年代使用率的变化。正常服务的老年代曲线应该像呼吸一样上升到某个阈值触发回收下降再上升。如果每次下降之后的高点越来越高或者某次回收后只能降一小截然后快速回升那基本就是泄漏或者大对象堆积的典型特征。我们当时采了 15 分钟发现老年代从 62% 匀速涨到 84%触发一次 Full GC回落到 75%然后又继续涨。每次回收净增的底都在缓慢抬高这说明每轮回收后残留的可达对象在变多。这个结论直接把我们指向了堆转储因为只有拷出堆内存才能看清到底是哪些对象赖着不走。顺便说一句jstat 是个很轻量的命令生产环境用没问题但要注意别在高峰期长时间高频采样pid 本身占用资源很少实在不放心就用jcmd pid GC.class_histogram这种一次性命令代替。2.3 堆转储抓到真凶拿到 jstat 的证据之后我们在 Full GC 刚结束、老年代使用率处于低位的时候连续抓了两份堆转储。抓的时机很关键如果抓得太晚老年代塞满之后全是垃圾反而看不出嫌疑对象。命令是这样jmap -dump:formatb,file/opt/logs/heap-20241202.hprof pid这份 dump 有 4 个 G拿回本地用 Eclipse MAT 打开看 Dominator Tree 和 Leak Suspects Report。结果非常直接一个ConcurrentHashMap实例单独占了老年代将近 70% 的内存往里一钻看到的是几百万个 Long 类型的 Key指向一堆ArrayListRule对象。代码很快就定位到了。这个服务里有一个用户命中的优惠规则本地缓存写的非常随意public class UserSegmentCache { // key 是 userIdvalue 是匹配到的规则列表 private static final MapLong, ListRule CACHE new ConcurrentHashMap(); public static ListRule get(Long userId) { return CACHE.computeIfAbsent(userId, UserSegmentCache::loadRules); } }写这段代码的同学本意是减少重复计算但完全没考虑两个问题一是这个 Map 没有大小上限二是 key 是用户维度。平台每天有大量新用户访问每来一个新用户就往这个 Map 里塞一条永远不会移除。运气好的话老用户占比高Map 增长慢碰上大促拉新增长曲线直接就陡起来了。2.4 为什么这个缓存会把老年代塞满这里涉及一个很多人会忽略的点ConcurrentHashMap里的 key、value 全部是强引用而且这个 Map 被 static 字段持有意味着它本身就是 GC Root 可达对象。GC 判断对象能不能回收看的是从 GC Root 出发能不能追踪到它这条缓存链路上所有对象都可达所以年轻代里的这些缓存对象晋升到老年代后就再也回收不掉了。Full GC 不是没有努力它每次都能正常清理掉其他临时对象但几百万条缓存记录一个都清不掉。老年代的可用空间被这些死不了的对象逐渐蚕食可用水位越来越低最终每积累一段时间就必须触发一次 Full GC。而 Full GC 能腾出的空间有限所以每次回收完老年代使用率还是停在 75% 左右过一小时又涨满。这类静态集合缓存是 Full GC 高频的头号嫌疑犯。以后大家排查这类问题时看到老年代曲线一路抬高、Full GC 后降不下去第一时间应该怀疑的对象就是静态 Map 缓存、ThreadLocal 维护的线程上下文、以及注册了但从未反注册的监听器。3. 优化实施代码修复 JVM 参数改造3.1 第一步止血本地缓存重做根因明确了第一件事不是调 JVM而是先动手改代码。我们把这个用户维度缓存换成了 Caffeine 实现设置了最大条数和过期时间private static final CacheLong, ListRule CACHE Caffeine.newBuilder() .maximumSize(10_000) .expireAfterWrite(30, TimeUnit.MINUTES) .build(); public static ListRule get(Long userId) { return CACHE.get(userId, UserSegmentCache::loadRules); }这里有几个选择要说清楚。第一为什么用 Caffeine 而不是自己写清除逻辑Caffeine 底层是类似 ConcurrentHashMap 的结构支持 W-TinyLFU 淘汰算法性能好而且淘汰是惰性的不会专门起线程扫全表对 GC 压力小。第二为什么上限是 1 万我们对这个服务的活跃用户量做了统计高峰 30 分钟内活跃用户大概八九千1 万条足够覆盖热度同时对老年代的占用控制在几十 MB 级别远远构不成威胁。第三为什么加 30 分钟过期规则配置本身变化的频率很低30 分钟足够保证数据新鲜度。这里要提醒一句maximumSize只限制条数不限制单个 value 的大小。如果 value 本身是个很大的对象图还是要按字节数评估Caffeine 也支持maximumWeight。我们这条 value 里每人也只有几十条规则对象规模可控才放心用条数限制。3.2 第二步减负干掉循环里的 N1 调用修完缓存之后我们顺便翻了一遍这个服务的热点代码结果又找到一个加重老年代负担的隐患计算价格的时候循环里对每一个商品调一次远程规则服务。代码大致长这样for (Sku sku : skuList) { RuleResult result ruleClient.query(sku.getId(), userId); // 远程 RPC results.add(result); }一个购物车里可能有 50 个商品就意味着 50 次远程调用每次调用都要创建请求对象、响应对象、缓存对象、线程上下文对象。这些对象大部分在年轻代里就能回收但每一次 RPC 都会产生一批生命周期长的中间对象推高了晋升压力。改造很简单把单查接口换成批量接口ListRuleResult results ruleClient.batchQuery(skuIds, userId);单次 RPC 批量返回循环里的临时对象没了本地缓存命中率也上来了。实测这步改造之后服务每分钟的 Young GC 次数降了将近一半。GC 优化不一定非要在 JVM 参数上做文章很多收益其实藏在业务代码里只是平时没有 GC 视角看不到它们的存在。3.3 第三步布局把堆和代际结构调对代码层面的两个大头处理完之后Full GC 已经从每天 40 次降到了 3 到 5 次但离目标还远。这个时候才轮到 JVM 参数出场。我们重新梳理了这台机器的容量8 核 16G原配置是 4G 堆其他内存给了操作系统、缓存和中间件。压测显示业务峰值稳定运行需要 5 到 6G 堆于是我们把堆调到了 6G-Xms6g -Xmx6g -XX:NewSize2g -XX:MaxNewSize2g -XX:UseConcMarkSweepGC -XX:UseParNewGC -XX:CMSInitiatingOccupancyFraction70 -XX:UseCMSInitiatingOccupancyOnly这里有几个参数要解释。-Xms和-Xmx设成一样避免运行期动态伸缩堆带来的停顿和不可控。新生代固定 2G是因为这个服务的对象大多数朝生夕死年轻代给足空间能明显降低 Young GC 频率。CMSInitiatingOccupancyFraction70是告诉 CMS老年代占用到 70% 就开始并发标记清理提前动作而不是等到塞不下了才被迫 Full GC。UseCMSInitiatingOccupancyOnly让 JVM 严格遵守这个阈值别自作主张。这一步调完Full GC 频率降到了每天 2 次左右单次停顿时间也从 1.8 秒降到了 1 秒以内。但我心里清楚CMS 在老年代碎片化严重的时候还是不稳而且 JDK 8 的 CMS 迟早要退役与其等它在某次大促时突然罢工不如主动切换到 G1。3.4 第四步换代CMS 换 G1 的选型思考CMS 换成 G1 是个需要谨慎的决定不能因为网上说 G1 好就无脑换。我们当时做了几轮压测对比之后才最终切换。核心参数如下-Xms6g -Xmx6g -XX:UseG1GC -XX:MaxGCPauseMillis200 -XX:G1NewSizePercent20 -XX:G1MaxNewSizePercent40 -XX:HeapDumpOnOutOfMemoryError -XX:HeapDumpPath/opt/logsG1 和 CMS 最大的区别是内存布局G1 把堆分成一个个大小相同的 Region年轻代和老年代不再是物理连续的区域而是逻辑上的 Region 集合。它维护了一个预测模型会根据MaxGCPauseMillis动态调整年轻代大小尽量把每次停顿控制在你设定的值以内。对于响应时间敏感的服务这个能力很实用。但 G1 不是万能药。如果你的服务老年代里塞着大量长生命周期对象或者分配速率极高G1 的混合回收也会力不从心甚至出现 Full GC。我们是在代码层已经清掉缓存泄漏和 N1 之后才切 G1 的基础环境变健康了G1 的效果才好。顺序反过来的话大概率会得出G1 也不过如此的结论。切换的过程按灰度走先在压测环境跑全量回归确认停顿指标达标再线上放一台机器观察两天确认稳定后才全量铺开。切换后观察一周Full GC 从每天 2 次直接降到了 10 天 1 次单次停顿稳定在 800ms 以内大部分时候甚至不会触发 Full GC只有老年代整堆对象特别多的时候才会兜底回收一次。3.5 上线效果从 40 次降到 10 天 1 次数据是这次优化最好的证明。三个阶段的效果对比放在一起看指标优化前代码修复后CMS参数调整后CMSG1 切换后Full GC 次数40 次/天3~5 次/天1~2 次/天1 次/10 天单次 Full GC 停顿平均 1.8s平均 1.2s平均 0.9s平均 0.8sYoung GC 次数约 1300 次/天约 900 次/天约 750 次/天约 600 次/天接口 p99860ms430ms280ms210ms上游超时率0.85%0.23%0.06%0.02%这个表也说明了另一个道理GC 优化是一个系统性问题代码、参数、收集器三轮下来每一步都在往前推。单独调参数可能也能把 Full GC 压到很低但代码里的泄漏不清掉总有一天会反噬。4. 配套能力建设让 Full GC 无处遁形4.1 监控告警不要只在事发后尖叫这次排查最痛苦的一点是初期告警只有超时率这一条GC 指标全靠人肉去查。问题修复之后我们把 GC 指标接入了 Prometheus用 jmx_exporter 暴露 JVM 相关数据Grafana 上建了一块专门的面板。告警规则也做了分级。原来只盯着 Full GC 次数现在更多关注老年代增长率。我建议至少配置这四条老年代使用率超过 70% 并持续 5 分钟warningFull GC 单次停顿超过 1 秒warningFull GC 频次超过 1 次/小时按服务特性定基线critical老年代使用率在每次 Full GC 后回落不足 20%critical。最后一条尤其有用它本质上是回收效率告警。如果 Full GC 后老年代使用率还是很高说明里面都是存活对象这种情况加参数没用要重新怀疑代码。当时我们要是早配了这条告警排查时间能省下至少两天。4.2 全自动化现场留存在事故发生时自动留证Full GC 调优最怕什么最怕出了事没有现场。评审之后我们给所有 Java 服务统一加上了 crash 留证参数-XX:HeapDumpOnOutOfMemoryError -XX:HeapDumpPath/opt/logs -XX:ExitOnOutOfMemoryError这里要特别说一下ExitOnOutOfMemoryError。之前团队遇到过 OOM 后进程半死不活、接口全部超时但进程还在的情况比直接挂掉更难处理。加了ExitOnOutOfMemoryError之后JVM 在抛出 OOM 时直接退出进程让容器编排系统把它重新拉起来恢复速度反而更快同时堆转储也留下来了。在非 OOM 场景我们也会配合 Arthas 的vmtool命令在 Full GC 频次异常的机器上手动抓取类直方图快速定位哪些类型的对象占了多少内存。这套组合拳下来下次再出问题证据留存基本是全自动的不用再熬夜人肉 jmap 了。4.3 发布闭环代码评审和压测怎么配合这次问题的根子是人写出来的代码所以要防复发必须把防线前移到代码评审环节。我们的做法是给评审清单里加了三类必查项有没有无上限的静态集合有没有在循环里做远程调用有没有按用户维度缓存数据且没有淘汰策略压测环节也补了课。之前压测只看吞吐量和响应时间现在还会对比压测前后的 GC 指标老年代曲线是否平稳、Full GC 频次是否在可接受范围、压测结束后堆内存能不能降回基线。这个压测后回落检查非常关键很多内存问题只有在流量上涨时才会暴露而压测恰恰是模拟流量的最好时机。5. 复盘与避坑清单5.1 Full GC 排查路线图速查表把这次的经验浓缩成一张速查表方便大家遇到问题直接对号入座阶段关键动作工具/参数关注点现象确认确认 Full GC 是否和业务抖动相关监控曲线叠加时间是否对得上数据收集开启 GC 日志jstat 采样-Xloggc, jstat -gcutil老年代趋势趋势判断判断是泄漏还是内存不足观察 FullGC 后回落幅度回落低于 20% 高度疑似泄漏根因定位抓堆转储分析支配树jmap, MAT找大对象和静态持有代码修复修缓存、修循环调用Caffeine, 批量接口消除强引用堆积参数调优重设堆大小和代际比例-Xms/-Xmx, NewRatio按业务峰值定收集器换代压测后灰度切换G1, MaxGCPauseMillis盯停顿和吞吐长期保障监控、告警、评审、压测Prometheus, 清单防复发5.2 我踩过的几个典型 GC 坑第一个坑是盲目加堆。最开始我们试过把 -Xmx 直接从 4G 提到 12GFullGC 确实从 40 次降到了 25 次左右但单次停顿时间从 1.8 秒涨到了 4 秒多用户体感更差了。堆越大Full GC 扫描的对象越多停顿时间越长这是一个平衡题不是越大越好。第二个坑是忽略System.gc()。排查中看到日志里有一批特殊触发的 Full GC顺着堆栈查下去发现是某个监控组件周期性调用了System.gc()。后来通过-XX:DisableExplicitGC把它禁掉了少数确实需要主动触发 GC 的场景我们又单独在代码里显式处理不再放任这种隐式调用。第三个坑是直接用默认 G1不调G1HeapRegionSize。小堆用默认 Region 大小问题不大但我们压测时发现大对象分配会直接引发 Full GC后来把 Region 调到了 16MB并配合-XX:G1NewSizePercent控制年轻代弹性情况才好转。第四个坑是只盯 Full GC 次数不看暂停时间的分布。有些优化表面上看次数降了但单次停顿反而变长对业务伤害更大。优化前后的对比应该同时看频次、单次停顿和总暂停时间三个指标缺一个都可能被骗。5.3 复盘完想说的几句实在话这次把 Full GC 从每天 40 次优化到 10 天 1 次技术层面其实没有太高深的东西无非是日志、jstat、堆转储、参数调整这些常规手段。真正难的是排查顺序先确认现象、再收集数据、判断趋势、定位根因、最后才动参数。顺序对了问题通常不难解顺序错了很容易陷入反复调参的死循环。我个人的体会是GC 优化最核心的功夫不在 JVM 参数上而在写代码的人心里。一个无上限的缓存、一个循环里的远程调用写的时候不觉得什么上了生产就变成老年代的定时炸弹。优化完这个月我把团队里的代码评审清单更新了一遍也给新人专门讲了一次GC 视角看代码的分享。以后业务代码里再出现类似隐患至少评审阶段就能拦住一大半。最后再说一个操作上的小技巧每次调整完 GC 参数别急着一次全量上先在压测环境用两倍峰值流量跑 20 分钟看老年代曲线能不能稳定再灰度一台线上机器跑 24 小时。宁可多花一天验证也别在线上一夜回到解放前。