大概一个多月前我接到一条让我头疼不已的告警某个订单查询接口的 P99 延迟从平时的 80ms 一路飙到 800ms 以上CPU 使用率每隔几分钟就像过山车一样冲到接近 100%。一开始我照例查了流量、数据库慢查询、第三方依赖全都没有异常。真正让我锁定怀疑目标的是监控里那组刺眼的 JVM 数据——Young GC 每分钟接近 20 次甚至每隔 5 到 10 分钟还会出现一次 Full GC。于是我把排查重心从“怎么调 GC 参数”转移到 JFR 录制结果上最终发现这场 GC 频繁问题的根源根本不在收集器配置而藏在业务代码每一次不起眼的对象分配里。这篇文章完整记录这次从 JFR 到代码优化的排查过程希望给同样被 GC 频繁折磨的后端同学一条可复制的路径。1. 先看现象一个“接口变慢”告警背后的 GC 异常1.1 业务侧反馈与第一轮监控排查那天下午四点刚过值班群就有人开始刷屏订单列表接口大面积超时客户端页面卡顿部分请求要等三秒以上。我没有急着上服务器而是先打开监控面板做了三件事确认流量是否突增、确认依赖的数据库与缓存组件是否有故障、确认网络和容器资源是否正常。结果这三项全部排除说明问题大概率出在应用进程自身。然后把目光放到 JVM 指标上问题立刻显现CPU 的 user 占比周期性抬升GC 曲线像锯齿一样密集Young GC 每分钟 15 到 20 次间隔不到 3 秒更严重的是每 5 到 10 分钟会触发一次 Full GC暂停时间从 800 毫秒到 2 秒不等。对比我们平时的表现——Young GC 每分钟 5 到 8 次Full GC 一天难得出现一次——这个差距足够说明系统进入了一个异常分配状态。我额外做了一步拉出最近两周的 GC 数据作为基线确认这不是监控口径变化也不是近期上线引入的偶发问题。这里建议大家把“基线”养成习惯没有基线你很难判断一次 GC 频率升高到底是真异常还是本来就如此。1.2 为什么“先调堆参数”这条路走不通拿到结论后群里已经有同事提议“堆不够大先加内存、把 GC 参数调一调”。这种思路在表面上完全合理但真正动手前我问了自己一个问题垃圾回收只是清理垃圾GC 频繁的本质应该是垃圾的产生速度大于回收速度。如果分配速率不掉下来就算把堆从 4G 调到 8G也只是把 Full GC 的间隔从 5 分钟拉长到 10 分钟问题迟早会回来。打个比方一个房间不断有人往里扔垃圾再大的垃圾桶也只是延后垃圾满溢的时间。我们要找的是那个“不断扔垃圾的人”。对应到 JVM 里就是要找到“谁在持续分配对象、分配了什么对象、分配了多少”。这个问题的答案GC 日志不直接给堆转储也难定位最好用的是现场采集一份 JFR 记录去看对象分配采样。当然调堆参数不是完全没用。当 GC 现象只是堆容量规划不足、对象分配速率本身合理时适当增大堆或调整新生代比例确实有效。但在本例中GC 频繁伴随明显的分配热点回收端再怎么优化都只是拖延时间。所以我的判断是先分析“谁在分配”而不是先动“怎么回收”。2. JFR 取证低开销的“黑匣子”是怎么录到现场的2.1 JFR 的核心价值与基本采集方式JFR 全称 Java Flight Recorder是 JDK 自带的飞行记录器设计思想和飞机黑匣子类似平时以极低开销持续记录运行时事件出问题后把最近一段记录导出分析。官方标注的开销一般能控制在 1% 以下所以生产环境长期开启是常见做法。它记录的内容很丰富GC 事件、对象分配采样、锁等待、文件与网络 IO、线程 CPU 使用等。正是这种“持续记录 事后分析”的模式让我们不用等到下次故障再去复现现场。采集方式主要有三种启动参数静态开启、jcmd 命令动态开停、JMX 开启。最常用的是前两种尤其是服务已经出问题时用 jcmd 动态开启最合适# 方式一启动时开启滚动录制保留最近 200MB 的记录 -XX:StartFlightRecordingdisktrue,maxsize200m,settingsprofile # 方式二进程启动后动态开启适合正在排查问题的场景 jcmd pid JFR.start namegc_check settingsprofile duration10m jcmd pid JFR.check jcmd pid JFR.dump namegc_check filename/tmp/gc_check.jfr jcmd pid JFR.stop namegc_check这里有三个点要解释清楚。第一settingsprofile 比 default 采集的事件更密集会额外包含对象分配采样、方法采样等高密度事件定位性能问题基本都要用 profile 级别。第二duration10m 是我推荐的起点至少要覆盖两个 GC 高峰周期否则录到的时间窗口可能全是业务低峰看不出问题。第三JFR.dump 可以在录制进行当中随时提取一份快照不影响后续录制如果服务已经撑不住dump 完也要尽快 stop避免文件持续膨胀。如果你还在 JDK 8需要确认你用的发行版是否内置 JFR较新的 8u272 以后版本已经内置JDK 11 之后更是完全集成在标准发行版里。老版本里常见的“商用特性开关”在现在的版本里已经不再需要。2.2 录制时的四个关键注意事项录制现场看着简单但有几个细节踩过坑之后我再也没忽略过。尽量不要重启服务。重启会把现场冲掉也会让流量路径变化。很多同学遇到 GC 问题第一反应是重启“缓一缓”但等你缓完可以用于定位的现场也丢了。只要没有 OOM 到完全不可用就先开 JFR 再决定下一步。确认磁盘空间。profile 级别 10 分钟的文件通常几十 MB 到几百 MB具体取决于业务分配量用 maxsize 限制滚动大小避免磁盘被 JFR 文件打满这是运维同事最担心的事。注意文件存放位置。如果直接写容器本地磁盘容器一旦销毁文件就没了复盘时很尴尬。我一般会让 jcmd 先写到临时目录确认录制完成后立刻 dump 到持久化目录再同步一份到分析机。如果同时怀疑 CPU 问题可以同步用火焰图采样工具采集 CPU 调用栈和 JFR 数据交叉验证。JFR 的重点是“对象分配”CPU 采样重点是“谁在消耗 CPU”两者结合往往比单看一个更准。3. 数据解析从 GC 事件到分配热点的三层递进3.1 第一层GC 事件的宏观画像拿到 jfr 文件后我用 JDK 自带的图形化分析工具打开也用了命令行方式快速过滤jfr print --events jdk.GCPhasePause,jdk.GarbageCollection /tmp/gc_check.jfr先做宏观画像看 GC 类型、触发原因、堆使用率变化、暂停时间。这里看到的结果印证实了监控层面的判断Young GC 极其频繁而且每次 GC 之后老年代的增长比例明显偏高。这不是一个健康信号——年轻代回收后大量对象本该被清掉但总有一部分活对象快速晋升到老年代让老年代空间被慢慢顶高。还有一个细节值得注意老年代增长快不一定是“对象活得太久”更可能是某些大对象大数组、大字符串、大 JSON 缓冲区直接越过细粒度分配路径甚至在年轻代回收时很快晋升。也就是说宏观层面的现象已经从“GC 频繁”推进一步——对象分配量大而且大对象占了不少比例。3.2 第二层TLAB 与对象分配采样要回答“谁在分配”需要理解 TLAB 和 JFR 的两个核心事件。TLAB 是 Thread Local Allocation Buffer 的缩写每个线程在新生代 Eden 里维护一块私有缓冲绝大多数小对象都在 TLAB 内无锁分配效率很高超过 TLAB 大小的大对象会走 TLAB 外的分配路径对应 JFR 里的 jdk.ObjectAllocationOutsideTLAB 事件。而 jdk.ObjectAllocationSample 事件会按一定采样率记录对象分配的调用栈和分配字节数是定位“谁是垃圾生产者”的主力。实际操作时我在图形化工具里打开 Object Allocation 页面按 Allocation 字节数从高到低排序前 20 个调用栈基本就能覆盖大部分分配总量。我看到的前几名清一色指向内部一个订单服务里 OrderQueryService 的 listOrderViews 相关调用栈分配的对象类型主要是 byte[]、String 和 OrderView/Map 的实现类。这里不要被 byte[] 迷惑它经常是字符串的底层载体、JSON 序列化的输出缓冲。关键要看调用栈的入口方法。到这里调查已经顺势从“JVM 层”切换到“代码层”。3.3 第三层调用栈交叉验证排除锁的干扰有些场景里 GC 频繁只是表象真正卡住业务的是锁竞争或 IO 等待。JFR 里有独立的锁事件例如 jdk.JavaMonitorEnter、jdk.ThreadPark。我专门看了这两类事件锁等待虽然存在但次数和时长与 GC 暂停完全不在一个量级线程 CPU 负载事件也显示 user CPU 占比高说明线程确实在忙于计算和分配而不是挂起等待。交叉验证很重要。如果只看到分配热点就急着改代码很可能忽略“某些线程分配是因为拿到锁之后才继续跑”这种间接关系。通过锁事件、CPU 事件、IO 事件一起对照才能放心地把问题定性为“分配型 GC 压力”而不是“锁等待造成的伪 GC 假象”。4. 代码定位揪出“隐形高频分配”的源头4.1 热点栈背后的真实代码顺着热点栈翻到源码代码本身并不复杂甚至第一眼会觉得“挺正常的”。我把问题代码简化成下面这种形态public ListOrderView listOrderViews(ListString orderIds) { ListOrderDO orders orderDao.batchQuery(orderIds); ListOrderView views new ArrayList(orders.size()); for (OrderDO order : orders) { OrderView view new OrderView(); copyCommonFields(order, view); // 20 个字段全量拷贝 view.setExtInfo(JsonUtils.toJson(order.getExtMap())); // 扩展信息序列化成字符串 views.add(view); log.debug(order detail: {}, JsonUtils.toJson(order)); // 每单都先拼好 JSON String tags ; for (String tag : order.getTagList()) { tags tags tag ;; // 循环里不停创建新字符串 } view.setTags(tags); } return views; }这些代码功能上完全正确本地拿几十条数据测也毫无感觉。问题出在“量”上单次请求要处理 5000 条订单每条订单平均产生两三百个临时对象包括 DTO、String、char[]、byte[]、JSON 序列化的中间缓冲等等一次请求就是上百万个对象。接口在高峰期并发几十个每秒几千万个对象堆再大也扛不住这种分配速度。4.2 三个反直觉的分配吞金兽第一循环内的字符串“”拼接。很多人以为 javac 会把 String 拼接优化成 StringBuilder所以没事。但优化是有条件的简单语句会被优化循环内连续拼接这样的复杂表达式编译器和运行时都难以完全消解中间对象。即使 JDK 9 之后采用动态字符串拼接高频循环里依然会产生大量临时对象。正确做法是提前建一个 StringBuilder 复用或者干脆延迟到真正需要展示字符串的时候再拼。第二日志参数在方法调用前已经求值。上面代码里的log.debug(order detail: {}, JsonUtils.toJson(order))看起来无伤大雅实际上JsonUtils.toJson(order)是在进入 debug 方法之前就执行完的。哪怕日志级别是 info这行 JSON 序列化也会照做产出一个完整的字符串然后被立刻丢弃。这是典型的“白干活 大量垃圾对象”。这次排查里这个隐形垃圾的贡献非常大。第三DTO 全量拷贝。接口下游可能只需要四五个字段我们却把 20 多个字段全量拷贝了一遍扩展 Map 还要转成 JSON 字符串。每多拷一个字段、每多转一次字符串就有额外的 byte[]、char[]、String 产生。高频路径上少构造一个对象比单纯把堆调大 1G 有效得多。4.3 顺藤摸瓜缓存集合的无上限增长分配热点解决到一半我又回头看了 JFR 的 GC 事件虽然 Eden 分配压力大但周期性的 Full GC 更像是老年代被慢慢顶爆。于是多翻了一层代码发现服务里有一个 static HashMap 用来做用户订单视图的本地缓存只有 put没有淘汰。缓存对象长期存活新数据不断替换旧数据旧对象就成了老年代里的垃圾。这种无上限缓存是 Full GC 的经典引火线。结论很明确一次 GC 频繁问题往往不是单一代码坏味道而是“高频分配 无界缓存 日志浪费”叠在一起。排查时要顺着现象把所有相关的现场都找出来别修完一个点就收工。5. 优化方案落地与前后数据对比5.1 四个优化点与具体改法优化方向一共四条每条改动都很小但叠加起来效果显著。第一条高频循环内的字符串拼接改为复用 StringBuilder并给一个合理初始容量减少扩容次数StringBuilder sb new StringBuilder(32); for (String tag : order.getTagList()) { if (sb.length() 0) { sb.append(;); } sb.append(tag); } view.setTags(sb.toString());第二条日志序列化延迟到真正打印时才执行。最直接的做法是删掉低价值的明细日志或者用日志框架的 Supplier 延迟参数如果确实需要整单对象应该传对象引用本身让日志框架在判断要输出时才触发 toString而不是调用前就拼好 JSON 字符串。第三条裁剪 DTO 拷贝。和下游确认字段清单后只保留五个必要字段扩展信息也从“整个 Map 序列化成 JSON 字符串”改成“只提取必要字段的轻量结构”。这一步保证了接口语义不变但每个请求少了几十个临时对象。第四条给静态缓存加上容量上限和过期淘汰机制从机制上保证老年代不会因为缓存无限增长而被慢慢撑爆。5.2 压测与 JFR 复测用数据说话测试环境用录制好的真实流量回放压测同一个服务、同样的并发和请求体分别采集优化前后的 JFR 和监控数据结果如下指标优化前优化后每分钟 Young GC 次数18 次4 次Full GC 频率每 8 分钟 1 次0 次平均对象分配速率约 320 MB/min约 85 MB/min接口 P99810 ms110 msCPU 峰值使用率99%55%我最关注的其实不是 GC 次数而是分配速率。GC 次数会受堆大小、回收时机影响分配速率更直接反映垃圾产生速度。从每分钟 320MB 降到 85MB说明确实改到了点子上。发布到生产后我又做了一次 10 分钟 JFR 采集分配热点已经不在原先那几个方法上GC 曲线也稳定下来。5.3 上线后的 48 小时观察发布后我没有立刻收工而是观察了完整的 48 小时跨过了两个业务高峰。观察项包括 GC 曲线、P99、CPU、告警通知。期间也踩了一个小坑发布后第一个小时内 GC 次数比预期多一点一开始吓一跳后来确认是类加载、缓存预热、少量热点触发代码路径切换造成的峰值过后自然回落。建议大家做优化复盘时给“预热期”留出缓冲别用发布后几分钟的数据直接下结论。48 小时后告警彻底消失P99 稳定在 100ms 上下Full GC 连续几天没有出现。这个案例才算真正闭环。6. 方法论沉淀GC 频繁问题应该怎么快速定位6.1 一条可复用的排查链路整个过程如果压缩成一张清单大概是确认现象与基线 → 采集 JFRprofile 级别覆盖一个高峰周期→ 看宏观 GC 事件 → 按分配字节数排序找热点栈 → 交叉验证锁、IO、CPU → 回到源码定位分配点 → 小步优化 → 同条件 JFR 复测 → 灰度发布 → 观察 48 小时。这条链路里最容易被跳过的步骤是“同条件复测”很多人改完代码没有录第二次 JFR连优化到底有没有效果都不知道。还有一个原则值得反复强调先治分配端再考虑回收端。调堆、换收集器属于回收端的优化它们解决的是“垃圾来了怎么更快收掉”如果垃圾的产生速度本身就很离谱回收端怎么优化都是杯水车薪。6.2 平时可以做好的三件小事第一常开 JFR 滚动录制。生产环境长期开 profile 如果顾虑开销可以先开 default 级别的滚动录制遇到紧急问题时用 jcmd 动态切到 profile 补录。出事时能立刻拿到现场比什么高级技巧都重要。第二监控指标里加上 GC 频率、暂停时间和对象分配速率并设好基线告警。没有基线告警就是一堆数字有基线才能第一时间判断异常程度。这次如果不是提前有历史数据对比很难判断 GC 频率升高到哪个阈值才算事故。第三代码 Review 增加“高频路径分配意识”循环里尽量复用缓冲区、日志参数不预计算、DTO 只拷贝必要字段、静态集合必须带容量上限。这些检查点成本很低收益却非常直接能挡住一批最典型的 GC 频发问题。6.3 最后再说点个人经验这次排查让我印象最深的不是某个参数或者某个工具而是对“GC 频繁”这四个字的理解方式它从来不是堆调大一点就能解决的终点而是一扇通往代码质量问题的门。JFR 的价值在于把“看不见的分配”变成“看得见的调用栈”剩下的就是顺着栈一路走到源码改掉那些每秒钟都在浪费 CPU 和内存的坏味道。如果你也想在日常工作中快速上手我的建议是现在就选一个非核心服务打开 JFR 滚动录制然后跑一次 jfr print先看看你们系统里每分钟分配多少字节、前几个热点栈是什么。很可能不用等到故障你已经能发现一两个值得优化的点。这个动作花不了半小时但能把下一次性能排查从“焦虑的猜”变成“有数据的查”。