前阵子排查一个微信生态下的高并发消息下发服务RT 毛刺频繁冲到 1 秒以上GC 日志里满屏都是 Young GC可 Full GC 却并不算多。刚开始我下意识想调堆大小但折腾了两天没效果后来切到 JFRJava Flight Recorder做完整的时间线分析才真正看清了问题所在。这篇文章就用我这次排查经历作为主线分享怎么用 JFR 定位 Java 高并发服务里的 GC 瓶颈包括采集配置、JMC 分析思路、真实案例和避坑事项。适合正在头痛 GC 问题、想用一个低成本工具做系统性诊断的 Java 开发者。1. 为什么我最终把JFR当作高并发服务GC排查的第一工具1.1 传统GC排查方式的三个痛点很多人排查 GC 第一步就是看 GC 日志或者用 jstat 盯数据。jstat 确实方便但它只能看当前这一小段时间的实时数据服务一重启、问题一过现场就完全没了。对排查偶发性问题来说jstat 最大的问题是没有回溯能力你盯着的时候一切正常你一移开视线毛刺就冒出来。GC 日志是另一个常见选择但它有几个很尴尬的约束。第一GC 日志必须在 JVM 启动时就把参数加上很多存量服务根本没有开启出问题后拿不到任何记录。第二-XX:PrintGCDetails在吞吐量高的服务里会产生大量日志文件不少团队因为磁盘压力会选择关掉或者只保留很短窗口。第三GC 日志虽然能告诉你某次 GC 花了多少时间但它很难把“GC 暂停”和“业务代码里哪块逻辑在制造垃圾”对应起来你只能看到一个结果看不到原因链条。还有一个常见的坑是 jmap。高并发线上服务本身压力就大jmap -dump 可能会触发一次较长的停顿某些极端情况下还会加剧 Full GC。我在生产环境基本不敢轻易用 jmap 去做完整堆转储。至于 jstack 和 top它们能看线程状态和 CPU 使用率但对于“为什么 GC 频繁”“为什么单次 GC 这么久”这类问题信息维度明显不够。1.2 JFR的“黑匣子”定位和低开销设计JFR 解决的就是这些痛点。它从 JDK 11 开始开源并内置在 JDK 里设计目标就是对运行中的应用程序做低开销、持续性的采样与事件记录。注意一个关键词持续。JFR 可以像飞机上的黑匣子一样一直开着在环形缓冲区里滚动保留最近一段时间的数据。等线上出问题之后你再执行一次 dump 命令把历史记录导出成一个 .jfr 文件就能看到故障发生前后的完整内部状态。这一点对高并发服务尤其重要。高并发场景下的 GC 问题往往不是持续恶化的而是突发性的比如某个热点活动上线后流量涨了几倍或者某个消息扇出逻辑导致分配速率暴涨。如果没有持续记录等你发现问题时已经晚了而 JFR 的持续模式保证了你永远有一段“案发时间线”可查。另外JFR 的低开销做得确实不错。它主要基于采样和事件机制不会像一些重量级 profiler 那样大幅改变程序行为。官方公布的性能影响目标是低于 1%实际使用中要根据你的 settings 配置来评估但比起动不动就带来明显停顿的工具JFR 对生产环境要友好得多。更重要的是JFR 记录的内容不是单一维度的 CPU 采样而是把 GC 事件、堆分配采样、对象统计、线程活动、锁竞争等全部放在同一条时间线上。定位 GC 瓶颈时你能同时看到“哪段代码在分配对象”“GC 在什么时候停顿”“停顿期间线程在做什么”这种跨维度关联能力是传统工具难以替代的。2. 上线JFR前先把这些采集参数和运行机制搞清楚2.1 JDK改动大环境和JFR如何开启先说一个基础但容易踩的版本问题。JDK 11 及之后的版本JFR 是直接内置且开箱即用的不需要额外解锁参数。而 JDK 8 的情况比较复杂Oracle JDK 8u262 之后和 OpenJDK 8u272 版本之后也支持 JFR但此前需要用-XX:UnlockCommercialFeatures -XX:FlightRecorder这类解锁参数且有些发行版的 JDK 8 根本没有打包 JFR 组件。所以我在给团队推 JFR 采集规范时第一步永远是把所有线上服务的 JDK 版本梳理一遍建议统一到 JDK 17 或至少是支持 JFR 的较新版本否则你参数写对了也可能无法启动记录。在 JDK 11 环境我常用的是启动参数直接开启持续记录-XX:StartFlightRecordingdisktrue, \ namecontinuous, \ maxsize512M, \ maxage12h, \ settingsprofile, \ filename/data/jfr/continuous.jfr -XX:FlightRecorderOptionsrepository/data/jfr-repo,stackdepth128这里的maxsize512M会限制环形缓冲区最多占用 512MB 磁盘maxage12h表示最多保留 12 小时内的数据。配置了这两个参数后JFR 会自动滚动覆盖你不需要担心磁盘被写满。settingsprofile表示使用 profile 模板它会记录更多细节比如分配采样、方法采样、IO 事件等对做 GC 深度分析很有价值。如果服务已经启动你也可以通过 jcmd 命令动态开启和导出记录jcmd pid JFR.start namegc-check settingsprofile maxsize512M maxage12h jcmd pid JFR.dump namegc-check filename/tmp/gc-check.jfr jcmd pid JFR.stop namegc-check动态开启最大的好处是不需要重启服务适合已经出问题、希望立即捕获现场的场景。而启动参数的方式更适合长期持续记录让 JFR 成为默认开启的基础运维能力。2.2 持续采集与一次性dump怎么选在确定采集方式之前建议先弄清楚一个思路你是在“事故复盘”还是“日常巡检”事故复盘时如果之前已经开过持续记录直接 dump 当前环形缓冲区里的数据即可。注意 dump 出来的文件会包含最近一段时间的所有记录时间窗口取决于 maxsize 和 maxage 的配置。如果服务很忙、分配量很大JFR 会自动优先保留较新的数据较早的数据可能被覆盖。所以我一般会把 maxsize 调大一些比如 1GB同时把 repository 放到单独的目录避免与其他日志争抢 IO。日常巡检时我通常用duration60s做一次快速采样然后让 JFR 先停掉。这种方式的优点是快速、不会留下长期占用磁盘的脏数据。但它的缺点是窗口太短如果服务在采样期间没有明显的 GC 活动你只能看到一堆“正常”的数据很可能漏掉周期性出现的高峰问题。对于要分析“高并发下的 GC 瓶颈”的场景我更推荐高峰时段开启 30 分钟到 1 小时的记录或者干脆采用持续记录。2.3 容器环境下的JFR使用注意点现在的服务基本都在 Docker/K8s 里跑容器环境有几个细节需要特别留意。第一JFR 的 repository 和 dump 文件路径一定要写到持久化卷上。我曾见过同事排查 GC 问题时开启 JFR结果容器因为内存压力被调度重建重建后 JFR 文件全部丢失。建议在容器启动参数里把repository指向挂载的持久卷并定期用定时任务把 JFR 文件导出到中心存储。第二K8s 的内存 limit 是直接作用于容器的JFR 本身虽然内存开销不大但 profile 模式下采样事件会占用一定的 native 内存如果你的 pod 已经把内存压到很极限要留意 JFR 开启后是否有额外影响。第三容器内时间通常默认是 UTCJFR 时间戳也会基于容器内时间排查时最好先把时区对齐到业务监控系统的时区不然对时间线会很痛苦。3. 用JMC打开.jfr后我这样从数据里定位GC瓶颈3.1 先看GC配置和事件时间线别直接跳进结论用 JMCJDK Mission Control打开 .jfr 文件后第一个建议是克制住直接跳进某个视图的冲动先按顺序看三点。第一左侧 Memory 栏的GC Configuration。这里会告诉你 JVM 当前使用的收集器类型、堆初始值和最大值、新生代与老年代的大小、以及 G1 的 Region 大小等基础配置。很多时候问题一眼就能看出来比如-Xms和-Xmx设置不一致导致 JVM 一直在扩缩堆或者 Java 8 默认用了 ParallelGC 在高并发场景下停顿偏高而你完全没意识到。第二Garbage Collections视图里的时间线分布。不要把目光停留在平均数上要看 GC 事件的频率和单次耗时的分布。我会把时间轴拉到一个较长的窗口数一数每分钟发生多少次 Young GC单次 Global Pause 的耗时是稳定在一个低位还是偶尔突然飙高。如果一个服务的 Young GC 频率呈明显的周期性说明有某种定时任务在定期产生大量垃圾如果频率和业务流量高度相关那大概率是请求处理链路里的分配问题。第三看事件详情里每一个 GC 事件的阶段耗时。G1 的一次 Young GC 并不是一个不可分割的黑盒它内部有根扫描、RSet 更新、RSet 扫描、复制对象、引用处理等多个阶段。JFR 记录的事件可以展开看到各个阶段的耗时这能帮你快速判断单次 GC 时间长到底是因为存活对象太多、RSet 过于庞大还是引用处理太慢。这一步非常关键因为它决定了你后面是去优化代码、调参数还是换个收集器。3.2 Allocation Profiling把GC问题还原成分配问题如果只看 GC 事件你只能知道“GC 频繁”和“GC 停顿久”但不知道是谁在制造这些压力。JFR 最有价值的地方就在于Allocation Profiling视图它能直接告诉你堆内存分配的热点在哪里。这里补充一个背景知识JVM 分配对象的路径通常是先在 TLABThread Local Allocation Buffer里分配TLAB 满了再尝试从 Eden 区分配如果 Eden 也满了就会触发一次 Young GC。所以那些“生命周期极短、用后即弃”的临时对象才是导致 Young GC 频率高的主要凶手。JFR 会在分配路径上做采样记录下分配量较大的方法调用栈并统计这些栈累计分配的字节数。我拿到一份 JFR 文件后步骤基本是这样先看 Allocation Profiling 的 top 栈确认哪些方法分配的总字节数最大。通常你会看到 JSON 序列化、字符串拼接、日志对象创建、RPC 协议编解码这类常见热点。再对比 GC 事件的频率变化。如果 GC 频率和 top 分配栈的活动节奏高度吻合那基本可以确定问题在代码层。判断分配的对象是“需要长期保留”还是“临时垃圾”。如果大部分分配来自临时对象且老年代没有明显增长这就是典型的分配速率过高GC 是用来给这些临时对象擦屁股的。还有一点容易被忽略分配热点不一定等于 CPU 热点。有些方法因为大量分配触发 GC导致自身被频繁安全点暂停CPU 占用反而可能不高而有些 CPU 热点方法不分配对象对 GC 没有贡献。所以用 JFR 时我会把 Allocation Profiling 和 CPU 采样视图分开看不能混为一谈。3.3 区分四种常见GC瓶颈的信号综合我的经验高并发 Java 服务的 GC 瓶颈大致能分成四种类型每种在 JFR 里的信号都不一样。用一个表格来说明瓶颈类型JFR里的典型信号常见根因Young GC 频率高单次STW不高GC事件密集出现Allocation Profiling显示分配热点集中业务代码瞬时产生大量临时对象Eden容量相对不足Young GC 单次STW长单次GC事件耗时高G1各阶段里对象复制或RSet处理耗时占比大存活对象数量大RSet膨胀Region复制成本过高Full GC / Mixed GC 频繁老年代占用率持续高位GC配置中老年代空间小Full GC事件较多大对象直接进入老年代、晋升过快、老年代空间不足并发标记阶段CPU高GC事件里Concurrent Mark时长高线程CPU采样中出现G1标记线程热点老年代对象过多导致标记线程压力大CPU核数不足先对号入座别急着改参数。比如你看到的是类型一并伴有明显的分配热点那核心手段是减少对象分配而不是把堆调大。把堆调大只会让 Eden 区更大Young GC 频率暂时降低但每次 GC 的停顿反而可能更长对 RT 的影响未必改善。我自己踩过这个坑后面会展开讲。4. 一次真实排查微信消息服务Young GC频繁且STW不稳4.1 现象描述和初步怀疑这个服务是承载一个微信小程序消息下发的长连接网关JVM 堆 4GB使用 G1 收集器高峰期 QPS 大约 2 万到 3 万。现象是每天晚上高峰期和下午某个时段业务上报的 RT 99 线明显毛刺很多请求从几十毫秒跳到好几百毫秒偶尔冲到 1 秒以上。第一反应是看 GC 日志结果发现服务虽然开了 GC 日志但只保留了最近几个小时而且日志里没有显示 Full GC 很频繁满屏都是 Young GC间隔大概 1 到 2 秒就一次单次耗时在 100 到 300 毫秒之间波动。当时团队有人怀疑是堆太小想直接扩容到 8GB也有人想把 G1 的期望停顿时间调低还有人说 G1 就不适合这种场景干脆换 ZGC。我没有立刻做任何改动而是按照前面说的流程先给服务开启了 JFR 持续记录。因为问题会在高峰期定时出现我选择保留最近 12 小时的数据等下一个高峰时段过后再导出文件分析。4.2 JFR还原出来的完整因果链等第二天高峰期过去后我用 JFR.dump 导出了记录在 JMC 里打开后很快发现了几个关键信息。首先是 GC Configuration 里的新生代大小。服务虽然配置了 4GB 堆但 G1 的G1NewSizePercent默认比较低Eden 区实际可用空间不大。加上高并发时流量猛增Eden 很快被填满Young GC 被迫频繁触发。这说明频率高的问题确实和“内存空间被快速耗尽”直接相关但还没有说明为什么这么容易就被填满。接着看 Allocation Profiling事情就清楚多了。top 分配栈里排在最前面的几个调用路径全部集中在消息内容的构建和下发链路里。代码的逻辑是每来一条业务消息就创建一个“消息载荷对象”这个对象需要下发给所有在线连接。为了实现所谓的数据隔离代码里对每一个在线连接都复制了一份完整载荷再做一次序列化写入各自的 channel。换句话说一条热点消息如果有几百个连接需要下发累积分配就被放大了几百倍。再加上群消息场景下高峰期一条消息可能同时推给几千个连接分配速率直接飙升。JFR 统计的分配速率在高峰期接近每秒 3GB这个数值对于 4GB 堆来说非常夸张Young GC 不频繁才奇怪。第三个信息来自 GC 事件详情。单次 Young GC 耗时 100 到 300 毫秒主要时间花在“对象复制”和“RSet 更新”这两个阶段上。堆里短时间内产生了几十万个存活时间极短但尚未回收的临时对象GC 需要在安全点把所有线程暂停然后把年轻代里还活着的对象复制到 Survivor 区或晋升到老年代。因为临时对象太多GC 线程要处理的对象数量巨大STW 时间自然就长了。所以真正的因果链是代码层每个连接独立构建消息对象 → 分配速率暴涨 → Eden 快速填满 → Young GC 频率升高 → 大量存活对象与 RSet 处理导致单次停顿变长 → STW 期间请求排队 → RT 毛刺。这里还有个容易误判的地方老年代占用率其实不算高也没有明显的晋升失败但不是老年代的事问题全出在新生代的分配压力上。如果当时盲目扩容堆Eden 变大了Young GC 频率会暂时降下来但由于分配速率没变每次 GC 时需要扫描的存活对象反而更多停顿时间很可能不降反升。4.3 针对性优化和最终效果明确了因果链后我把重心放在减少分配上而不是调 GC 参数。核心改造有三点。第一把“消息载荷对象”改成不可变共享对象。一条业务消息只需要真正构建一次后续所有的在线连接都引用同一份对象不再为每个连接复制内容。这个改动直接砍掉了分配量的大头。第二序列化逻辑复用。原来的代码在每个连接的发包路径上都会 new 一个 JSON 序列化器我给改成线程级或请求级复用避免重复创建重量级对象。同时把 String 拼接改成直接操作 byte[] 缓冲减少中间字符串对象。第三对写缓冲做池化。每个连接的 channel 写缓冲原来每次下发都会新建我改造成一个可复用的缓冲池只在缓冲不够时扩容不再频繁申请新结构。GC 参数方面我只做了两处保守调整把-XX:G1NewSizePercent和-XX:G1MaxNewSizePercent从默认值调整到一个更稳定的范围让 Eden 不要随流量暴涨而出现明显的弹性波动适度增加了-XX:ConcGCThreads提升并发标记的处理能力。整体没有动堆大小也没有更换收集器。优化后的效果很明显分配速率从高峰期的每秒 3GB 降到 400MB 左右Young GC 从每 1 到 2 秒一次降低到几十秒一次单次停顿稳定在 20ms 以内RT 99 线也恢复到了正常水平。这个案例给我最大的启发是JFR 能把一个看起来像“GC 参数问题”的故障还原成“代码分配模式问题”方向对了改动量反而很小。5. 使用JFR排查GC时那些容易踩的坑5.1 不要靠一次临时采集下结论一次 1 分钟的 JFR 采集只能看到某个瞬间的快照用它来判断整体 GC 瓶颈非常危险。我之前分析过一个服务随口开了一次 30 秒的记录正好赶上低峰期看到 GC 一切正常就排除了 GC 问题。结果高峰期一过同一套记录再看一次完全不一样。后来我给自己定了两个原则一是周期性问题必须覆盖至少一个完整高峰周期二是长期巡检用持续记录遇到故障再 dump而不是临时去“拍一张照片”。如果服务里 GC 问题的触发条件是偶发的临时采集很可能什么都看不到。5.2 GC日志和JFR必须配合起来看JFR 是结构化的事件流信息维度丰富但它并不是万能的。GC 日志里-XX:PrintGCDetails输出的一些细节比如每个年龄代的对象晋升情况、GC 前后的详细堆状态有时候比 JFR 里的事件摘要更完整。排查晋升失败或老年代空间问题时我通常会同时打开 GC 日志和 JFR两边对一下时间点。另外JFR 中 GC 事件里能看到“VM Operation”这类原因但具体是什么触发了 Full GC比如是System.gc()还是堆分配失败GC 日志里往往描述得更直接。两边结合才能把事件链拼完整。5.3 JFR自身的开销、磁盘和版本问题长期开启 JFR 不是零成本的。profile 配置下采样频率高CPU 和 native 内存消耗会有一定上升。对已经处于高负载的服务建议实测一下开启前后的性能影响必要时可以修改stackdepth参数限制栈深度或者调整threadbuffersize控制线程级缓冲区。服务器磁盘方面JFR 文件虽然设置了 maxsize但在导出 dump 时如果磁盘空间不足会导致导出失败。我在生产环境会专门准备一个 20GB 以上的分区给 JFR 使用避免系统盘被占满。另外一个容易被忽略的问题很多人用第三方 JDK比如某些云厂商裁剪过的 JDK可能移除了 JFR 相关模块。线上排查前先跑一次jcmd pid JFR.check确认当前 JVM 是否支持 JFR否则配置了半天发现记录根本没启动会很耽误时间。5.4 关于G1参数调整的个人尺度最后说一个我总结出来的经验。看到 GC 问题大家第一反应往往是调参数G1 期望停顿时间、Eden 大小、Region 大小、Mixed GC 阈值。但 JFR 分析做得越多我越倾向于“少动参数、先动代码”。因为对于高并发服务GC 停顿往往只是症状分配压力才是病根。你调大了 Eden暂时降低了 GC 频率但单次 GC 停顿时间可能增加你调低了 Mixed GC 阈值老年代回收更积极但线程数和 CPU 消耗又会上升。除非你通过 JFR 看到非常明确的指向性信号比如某次 GC 的某个阶段耗时异常高否则不推荐在没有定位分配热点的情况下盲目套调优模板。从个人实际操作体会来看JFR 对我的最大价值是改变了排查的顺序。过去我是拿着 GC 日志猜现在我是先把 JFR 打开让数据自己说话。时间线摆在那里分配栈摆在那里哪一个类在制造垃圾、哪一段逻辑在放大内存压力全都清清楚楚。如果你也在面对高并发服务 GC 毛刺的困扰不妨先试着把 JFR 持续记录开起来等故障窗口过后再慢慢拆解我相信你会有不一样的发现。