2026/9/18 4:52:04
FEATURED · 精选文章 
上周四下午两点半运营同事在大群喊了一句“查询订单怎么这么慢”三分钟后监控告警也弹了出来——订单查询服务的P99延迟从平时的80毫秒直接飙到3.8秒同时有一台节点的CPU使用率接近100%。我登录服务器后第一件事就是看JVM状态jstat输出里的Full GC次数正肉眼可见地跳动不到一分钟就涨了好几次。这是一次非常标准的JVM Full GC事故现场服务变慢、CPU飙升、接口超时背后是堆内存被某些对象占满GC线程疲于奔命却回收不了多少空间。这篇文章把这次排查的全过程完整记录下来从告警触发、jps/jstat定位、GC日志分析、jmap导出堆转储再到用MAT顺藤摸瓜找到问题代码最后通过线程池改造和JVM参数调整收尾一条线走完。内容适合正在系统学JVM排查的工程师也适合想建立一套完整线上排查思路的同学——你在面试里被问到“线上Full GC怎么排查”时这套流程就是完整答案。1. 故障现场告警弹出到CPU飙升的半小时1.1 从监控告警看问题表象这次出问题的是订单查询服务一个标准的Spring Boot应用部署了四台节点。告警是这样的P99延迟从80ms飙升到3.8s环比上涨4700%其中一台节点CPU使用率打到98%其余三台在40%左右错误率没有明显上升但接口超时数量激增下游数据库连接池出现排队等待首先说明一点接口慢不一定就是JVM的问题也可能是数据库慢查询、下游服务变慢、网络抖动。但CPU打到98%这个信号很强基本可以排除数据库或网络的嫌疑因为纯等待型瓶颈不会让CPU爆表。下一步要确认的就是到底是不是GC在空转。另外我习惯先查一下发布记录。排查任何线上问题第一时间看最近有没有变更能少走很多弯路。这次查下来前一天晚上刚上线了一个“订单批量导出”功能时间和故障窗口完全吻合于是重点怀疑范围就缩小到了这个新功能上。1.2 排查前先理清思路你要找的是什么Full GC排查有一个核心思路不是问“怎么把GC调优调快”而是问“什么东西把老年代占满了”。对象不会凭空出现它们一定是被某段代码创建的并且由于某种引用关系一直存活导致回收不掉。只要找到这个源头问题就解决了一大半。所以我的排查顺序是固定的三步确认Full GC是真实且严重的频率、单次耗时、回收前后内存变化找出老年代里占用最大的对象是谁顺着对象引用链找到创建它的业务代码很多人一上来就调JVM参数把堆调大、换垃圾回收器这其实是在给症状吃止痛药。除非是明显的参数配置不合理比如堆太小、GC日志显示频繁晋升否则参数调整都应该排在定位代码问题之后。这次排查也再次印证了这一点。2. 用jstat和GC日志把Full GC现场钉死2.1 三秒上手jstat看JVM内存占用趋势排查第一步先确认JVM进程再用jstat看内存使用趋势。jps是最常用的找进程命令$ jps -l 21435 com.example.order.OrderQueryApplication 51876 sun.tools.jps.Jps21435就是我们要看的进程。接着用jstat查看GC情况-gcutil参数可以直接看到各内存区域的使用率和GC累计次数、耗时$ jstat -gcutil 21435 1000 5 S0 S1 E O M CCS YGC YGCT FGC FGCT GCT 0.00 0.00 12.52 99.79 97.16 96.71 12587 84.22 173 574.51 658.73 0.00 0.00 13.01 99.81 97.16 96.71 12588 84.23 174 577.94 662.17 0.00 0.00 13.87 99.83 97.16 96.71 12588 84.23 174 577.94 662.17 0.00 0.00 14.02 99.85 97.16 96.71 12589 84.24 175 581.40 665.64 0.00 0.00 14.55 99.87 97.16 96.71 12589 84.24 175 581.40 665.64每秒打印一次连续5次。这一组输出信息量很大O区老年代使用率99.79%而且一直在涨说明老年代基本满了FGCFull GC次数从173涨到175FGCTFull GC总耗时从574秒涨到581秒也就是说每次Full GC平均耗时接近3.3秒E区Eden使用率只有12%左右新生代并不紧张这里最关键的信号就是老年代满了每次Full GC都在做无用功。平均一次3秒多这个耗时放在订单查询服务上是致命的——期间所有线程都可能卡在GC安全点上接口请求全部排队等待。2.2 读GC日志Full GC前后内存变化说明什么jstat给了趋势GC日志则能还原更多细节。如果启动参数里加了-Xloggc:/data/logs/gc.log直接看最后一个Full GC的记录就够了2025-01-09T14:23:15.6810800: [Full GC (Allocation Failure) [PSYoungGen: 0K-0K(1835008K)] [ParOldGen: 4094980K-4094979K(2097152K)] 4094980K-4094979K(3932160K), [Metaspace: 123456K-123455K(1253376K)], 3.45 secs] [Times: user3.52 sys0.01, real3.45 secs]拆开解读PSYoungGen: 0K-0K(1835008K)新生代在Full GC前就是空的回收后还是空的说明对象都不是新生代升上去的或者说新生代早就被清空了ParOldGen: 4094980K-4094979K(2097152K)这是最要命的老年代从4GB只释放了1KB约等于没释放Metaspace元空间正常没异常3.45 secs用户态内核态实际耗时都指向这次GC非常耗时Full GC触发原因是Allocation Failure——堆上无法分配新对象了。但关键是回收之后老年代还是满的。这说明老年代里存的几乎全部是“活对象”它们被业务代码引用着GC没办法回收。如果每次Full GC之后内存能明显降下来再慢慢涨上去那是正常的容量问题像这种收了等于没收的情况基本可以断定是对象被错误地长期持有。再补充一个统计小技巧用grep配合awk可以快速数一下Full GC的发生频率和间隔分布grep Full GC /data/logs/gc.log | awk {print $2} | cut -c1-8 | uniq -c输出会显示每分钟发生多少次Full GC。我这边的结果是从14:20开始每分钟100多次后面越来越密集完全是失控状态。3. 用jmap导出堆转储顺藤摸瓜找到问题代码3.1 正确姿势生成heap dump文件定位到对象层面最直接的方式就是导出一份堆转储文件来分析。我用的是jmap命令如下$ jmap -dump:live,formatb,file/data/dump/heap-20250109-1430.hprof 21435 Dumping heap to /data/dump/heap-20250109-1430.hprof ... Heap dump file created [3984587777 bytes in 42.318 secs]这里有几个实操要点需要提醒加了live参数表示只导出存活对象文件会小不少但坏处是会触发一次Full GC。如果你的系统已经处于频繁Full GC的状态这一步可能让服务更卡。我这次是紧急处理能接受但如果系统完全没法动宁可别加live参数。导出期间应用会停顿最好选择业务低峰期操作。如果实在没办法也可以用jcmd GC.heap_dump相比之下和jmap差不多但功能更底层更稳定。导出的文件有3.7GB本地用MATEclipse Memory Analyzer打开之前一定要把MAT的内存调大。默认的eclipse.ini里-Xmx可能只有1GB打开这种文件直接报Java heap space需要改成-Xmx8g才行。如果不想导dump也可以用jmap先看一眼对象分布快速判断问题方向比dump轻量很多$ jmap -histo:live 21435 | head -30 num #instances #bytes class name ---------------------------------------------- 1: 1803364 1001079856 com.example.order.Order 2: 7213456 865614720 com.example.order.OrderItem 3: 12345678 524691315 [C 4: 987654 401237504 [B看到这个输出问题已经比较明显了Order对象有180万个实例占用约1GBOrderItem对象有721万个实例占用约865MB。这两个类加起来占了堆的一半以上而且它们都不是JDK内部类而是业务对象——这就是突破口。3.2 用MAT分析大对象从直方图到支配树打开hprof后我一般先看Histogram直方图确认哪些类型占用最大和jmap看到的一致。然后重点看Dominator Tree支配树它能呈现对象之间的持有关系告诉你“谁”是真正撑住整个内存的大头。这次支配树明显指向一个异常的持有链ThreadPoolExecutor$Worker (2个) -- java.util.concurrent.LinkedBlockingQueue -- LinkedBlockingQueue$Node -- com.example.order.export.ExportTask (约860,000个实例, retained heap ≈ 2.1GB) -- java.util.ArrayList -- com.example.order.Order (180万个实例) -- java.util.ArrayList -- com.example.order.OrderItem (721万个实例)也就是说一个LinkedBlockingQueue里塞了约86万个ExportTask对象每个Task里又带着一个包含Order和OrderItem的完整对象树总共占用了2.1GB的保留内存。看引用链这些Task被ThreadPoolExecutor$Worker持有着也就是在线程池的任务队列里排队等待执行但消费线程只有2个生产速度远高于消费速度任务越积越多最终把老年代直接塞满。用MAT里右键某个对象选择“Path to GC Roots”可以看到更具体的引用路径确认这些Task并不是临时状态而是被线程池长期持有。到这一步问题代码的轮廓已经出来了一个使用无界队列的线程池接收了大量携带重对象的生产任务消费不过来。3.3 顺着引用链到业务代码回看代码找到ExportTask的定义和提交逻辑问题立刻清楚了// 业务方法导出某个用户的全部历史订单 public void exportOrders(Long userId) { // 一次性把该用户所有历史订单全查出来 ListOrder orders orderService.listAllOrders(userId); // 把这一大坨数据封装成任务丢进线程池 exportExecutor.submit(new ExportTask(orders)); }问题根源有几个层次一个用户的全量历史订单可能包含几千甚至上万条ExportTask里直接持有整个ListOrder单个对象就很大大客户同时发起批量导出任务数量暴涨线程池队列是无界的任务只进不出内存无限增长老年代被占满后触发Full GC又因为任务都是存活的回收不掉形成一个恶性循环4. 根因落地线程池无界队列是如何拖垮JVM的4.1 问题代码还原与修复方案问题的核心不在JVM参数而在线程池设计。当时的线程池配置大概是这样的ExecutorService exportExecutor new ThreadPoolExecutor( 2, // 核心线程数 2, // 最大线程数 0L, TimeUnit.MILLISECONDS, new LinkedBlockingQueue() // 无界队列 );核心线程数2最大线程数2队列无界。当任务提交速度超过处理速度时新任务不会触发拒绝策略而是全部堆积在队列里。如果任务本身又是一坨大对象内存占用就会以非常快的速度膨胀。这个设计从内存安全角度讲几乎是“裸奔”的——没有任何机制能阻止队列无限增长。修复分两个层面。第一层是业务改造不能让一个任务承载全量数据// 分页拉取每页500条拆分任务 public void exportOrders(Long userId) { long pageSize 500; long total orderService.countOrders(userId); long pages (total pageSize - 1) / pageSize; for (int page 0; page pages; page) { ListOrder pageData orderService.listOrdersByPage(userId, page, pageSize); exportExecutor.submit(new ExportTask(pageData, page)); } }这样每个ExportTask最多持有一页数据500条订单记录单个任务的内存占用直降一个数量级。更重要的是如果总量很大但单页很小队列里即使堆积任务每个任务的“平均重量”也小得多。第二层是线程池改造必须使用有界队列并配置合理的拒绝策略ExecutorService exportExecutor new ThreadPoolExecutor( Runtime.getRuntime().availableProcessors(), // 核心线程CPU核数 Runtime.getRuntime().availableProcessors() * 2, // 最大线程2倍核数 60L, TimeUnit.SECONDS, new ArrayBlockingQueue(1000), // 有界队列最多1000个任务 new ThreadFactoryBuilder().setNameFormat(export-pool-%d).build(), new CallerRunsPolicy() // 队列满时由提交线程执行 );有界队列的意义在于一旦堆积超过1000个任务系统立刻感知压力触发拒绝策略而不是放任内存无限增长。这里选CallerRunsPolicy是因为它不会丢任务——队列满了之后由提交任务的线程比如Tomcat请求线程直接执行导出逻辑相当于把压力自然传导给上游起到削峰和限流的效果。相比AbortPolicy直接抛异常或者DiscardPolicy静默丢弃CallerRunsPolicy更稳妥。4.2 JVM参数与线程池参数一起调优代码修完之后JVM参数也要顺手调整。虽然根因不在参数但好的参数配置能让系统在遇到类似问题时更从容。修复前-Xms4g -Xmx4g -Xmn2g -XX:UseConcMarkSweepGC -XX:PrintGCDetails -XX:PrintGCDateStamps -Xloggc:/data/logs/gc.log修复后-Xms4g -Xmx4g -XX:UseG1GC -XX:MaxGCPauseMillis100 -XX:HeapDumpOnOutOfMemoryError -XX:HeapDumpPath/data/dump/ -XX:PrintGCDetails -XX:PrintGCDateStamps -Xloggc:/data/logs/gc.log几个调整的思考Xms和Xmx都设为4g避免JVM在运行期因为堆扩容、缩容产生额外停顿和不确定性从CMS切到G1倒不是说CMS不行而是在堆比较大、GC压力高的时候G1对内存碎片的容忍度更好Allocation Failure的触发频率会明显降低同时MaxGCPauseMillis100给了G1一个明确的暂停时间目标加上HeapDumpOnOutOfMemoryError这是所有生产服务都应该标配的参数一旦真正OOM会自动留下现场dump文件省去下一次靠运气抓堆的麻烦上线后验证效果也很直接压测时任务处理速度提升队列深度稳定在几十到几百的范围内不再无限增长连续观察一周Full GC从每小时200多次降到每天几次FGCT从574秒降到个位数P99延迟从3.8秒回到80毫秒上下。这次事故才算真正画上句号。5. 排查实录踩过的坑与工具速查5.1 最容易走偏的几个环节这次排查过程中我踩过或见过的坑不少都值得拿出来说一说免得你下次再走弯路。第一个坑是想当然地怀疑JVM参数。刚开始看到老年代99%占用我一度觉得是不是新生代太大导致对象过早晋升还想把-Xmn调小一点试试。后来结合GC日志看到回收前后老年代几乎没变化才意识到这不是晋升策略的问题而是老年代里的对象根本就没死。调参数前先看回收效果这是一条铁律。第二个坑是生产高峰期随意使用带live参数的jmap或jstat命令。jmap -dump:live会触发一次Full GC在系统已经很卡的情况下这一下可能直接把服务打成雪崩。如果业务不能接受停顿要么换用不带live的dump方式要么先用jmap -histo:live快速看个大概要么等到低峰期再做完整dump。我这次属于紧急情况事后想想其实有更稳妥的操作路径。第三个坑是只数Full GC次数不看单次耗时和回收后的内存差。一个系统如果Full GC次数多但每次只要几十毫秒、回收后内存明显下降说明GC在工作问题未必严重反过来像这次一样每次3秒多、回收等于没回收才是灾难。判断GC是否健康至少要看FGC、FGCT、O区变化这三个指标放在一起。第四个坑是排查前不看发布记录。其实如果早点把“订单批量导出”这个新功能纳入视野至少能提前一小时锁定方向。线上问题的黄金排查法则永远是先看变更再看指标最后才碰代码细节。5.2 工具速查表与核心心得把这次用到的排查工具和定位思路整理成一个速查表下次遇到类似问题可以直接照着过一遍。症状优先怀疑方向第一步操作FGC频繁且单次FGCT高老年代堆积大量存活对象jstat -gcutil pid 1000 5看O区变化和FGC趋势FGC频繁但单次耗时不高小对象频繁晋升、元数据膨胀看GC日志晋升情况调Survivor区大小或晋升阈值CPU高但GC正常业务线程死循环、锁竞争top -Hp pid找线程号再jstack看线程栈接口慢但JVM内存正常DB慢查询、下游依赖变慢先查APM链路和数据库监控别急着怀疑JVM常用命令备份jps -l定位Java进程jstat -gcutil pid 1000 5看GC趋势和内存区域使用率jmap -histo:live pid看对象数量与大小分布jmap -dump:live,formatb,filexxx.hprof pid导出堆转储jstack pid看线程栈配合top定位CPU热点jcmd GC.heap_dump -all xxx.hprof pidJDK自带另一种堆导出方式arthas的dashboard、heapdump、thread命令在线排查神器适合不想反复重启的场景最后再分享一个心得排查Full GC时我脑子里一直挂着的一句话是——“这些对象本来应该在什么时候死掉”所有的GC问题本质上都是对象生命周期被意外拉长了。循环引用的局部变量、没关闭的IO流、持有大对象的静态缓存、无界队列里的积压任务都是在阻止对象“按时死亡”。你只要顺着引用链找到那个不该存在的强引用问题就解决了。这次事故之后我把线程池队列深度监控也加上了。队列里积压多少任务是个比CPU和内存更早报警的指标。有时候问题还没把内存打满队列深度已经在疯狂上涨提前看到它就能在Full GC爆发之前把问题摁住。这个建议也推荐给你特别是手上有大量异步任务、导出导入、消息转储类业务的服务真的能救命。
一次JVM Full GC事故排查：线程池无界队列如何拖垮内存
上周四下午两点半运营同事在大群喊了一句“查询订单怎么这么慢”三分钟后监控告警也弹了出来——订单查询服务的P99延迟从平时的80毫秒直接飙到3.8秒同时有一台节点的CPU使用率接近100%。我登录服务器后第一件事就是看JVM状态jstat输出里的Full GC次数正肉眼可见地跳动不到一分钟就涨了好几次。这是一次非常标准的JVM Full GC事故现场服务变慢、CPU飙升、接口超时背后是堆内存被某些对象占满GC线程疲于奔命却回收不了多少空间。这篇文章把这次排查的全过程完整记录下来从告警触发、jps/jstat定位、GC日志分析、jmap导出堆转储再到用MAT顺藤摸瓜找到问题代码最后通过线程池改造和JVM参数调整收尾一条线走完。内容适合正在系统学JVM排查的工程师也适合想建立一套完整线上排查思路的同学——你在面试里被问到“线上Full GC怎么排查”时这套流程就是完整答案。1. 故障现场告警弹出到CPU飙升的半小时1.1 从监控告警看问题表象这次出问题的是订单查询服务一个标准的Spring Boot应用部署了四台节点。告警是这样的P99延迟从80ms飙升到3.8s环比上涨4700%其中一台节点CPU使用率打到98%其余三台在40%左右错误率没有明显上升但接口超时数量激增下游数据库连接池出现排队等待首先说明一点接口慢不一定就是JVM的问题也可能是数据库慢查询、下游服务变慢、网络抖动。但CPU打到98%这个信号很强基本可以排除数据库或网络的嫌疑因为纯等待型瓶颈不会让CPU爆表。下一步要确认的就是到底是不是GC在空转。另外我习惯先查一下发布记录。排查任何线上问题第一时间看最近有没有变更能少走很多弯路。这次查下来前一天晚上刚上线了一个“订单批量导出”功能时间和故障窗口完全吻合于是重点怀疑范围就缩小到了这个新功能上。1.2 排查前先理清思路你要找的是什么Full GC排查有一个核心思路不是问“怎么把GC调优调快”而是问“什么东西把老年代占满了”。对象不会凭空出现它们一定是被某段代码创建的并且由于某种引用关系一直存活导致回收不掉。只要找到这个源头问题就解决了一大半。所以我的排查顺序是固定的三步确认Full GC是真实且严重的频率、单次耗时、回收前后内存变化找出老年代里占用最大的对象是谁顺着对象引用链找到创建它的业务代码很多人一上来就调JVM参数把堆调大、换垃圾回收器这其实是在给症状吃止痛药。除非是明显的参数配置不合理比如堆太小、GC日志显示频繁晋升否则参数调整都应该排在定位代码问题之后。这次排查也再次印证了这一点。2. 用jstat和GC日志把Full GC现场钉死2.1 三秒上手jstat看JVM内存占用趋势排查第一步先确认JVM进程再用jstat看内存使用趋势。jps是最常用的找进程命令$ jps -l 21435 com.example.order.OrderQueryApplication 51876 sun.tools.jps.Jps21435就是我们要看的进程。接着用jstat查看GC情况-gcutil参数可以直接看到各内存区域的使用率和GC累计次数、耗时$ jstat -gcutil 21435 1000 5 S0 S1 E O M CCS YGC YGCT FGC FGCT GCT 0.00 0.00 12.52 99.79 97.16 96.71 12587 84.22 173 574.51 658.73 0.00 0.00 13.01 99.81 97.16 96.71 12588 84.23 174 577.94 662.17 0.00 0.00 13.87 99.83 97.16 96.71 12588 84.23 174 577.94 662.17 0.00 0.00 14.02 99.85 97.16 96.71 12589 84.24 175 581.40 665.64 0.00 0.00 14.55 99.87 97.16 96.71 12589 84.24 175 581.40 665.64每秒打印一次连续5次。这一组输出信息量很大O区老年代使用率99.79%而且一直在涨说明老年代基本满了FGCFull GC次数从173涨到175FGCTFull GC总耗时从574秒涨到581秒也就是说每次Full GC平均耗时接近3.3秒E区Eden使用率只有12%左右新生代并不紧张这里最关键的信号就是老年代满了每次Full GC都在做无用功。平均一次3秒多这个耗时放在订单查询服务上是致命的——期间所有线程都可能卡在GC安全点上接口请求全部排队等待。2.2 读GC日志Full GC前后内存变化说明什么jstat给了趋势GC日志则能还原更多细节。如果启动参数里加了-Xloggc:/data/logs/gc.log直接看最后一个Full GC的记录就够了2025-01-09T14:23:15.6810800: [Full GC (Allocation Failure) [PSYoungGen: 0K-0K(1835008K)] [ParOldGen: 4094980K-4094979K(2097152K)] 4094980K-4094979K(3932160K), [Metaspace: 123456K-123455K(1253376K)], 3.45 secs] [Times: user3.52 sys0.01, real3.45 secs]拆开解读PSYoungGen: 0K-0K(1835008K)新生代在Full GC前就是空的回收后还是空的说明对象都不是新生代升上去的或者说新生代早就被清空了ParOldGen: 4094980K-4094979K(2097152K)这是最要命的老年代从4GB只释放了1KB约等于没释放Metaspace元空间正常没异常3.45 secs用户态内核态实际耗时都指向这次GC非常耗时Full GC触发原因是Allocation Failure——堆上无法分配新对象了。但关键是回收之后老年代还是满的。这说明老年代里存的几乎全部是“活对象”它们被业务代码引用着GC没办法回收。如果每次Full GC之后内存能明显降下来再慢慢涨上去那是正常的容量问题像这种收了等于没收的情况基本可以断定是对象被错误地长期持有。再补充一个统计小技巧用grep配合awk可以快速数一下Full GC的发生频率和间隔分布grep Full GC /data/logs/gc.log | awk {print $2} | cut -c1-8 | uniq -c输出会显示每分钟发生多少次Full GC。我这边的结果是从14:20开始每分钟100多次后面越来越密集完全是失控状态。3. 用jmap导出堆转储顺藤摸瓜找到问题代码3.1 正确姿势生成heap dump文件定位到对象层面最直接的方式就是导出一份堆转储文件来分析。我用的是jmap命令如下$ jmap -dump:live,formatb,file/data/dump/heap-20250109-1430.hprof 21435 Dumping heap to /data/dump/heap-20250109-1430.hprof ... Heap dump file created [3984587777 bytes in 42.318 secs]这里有几个实操要点需要提醒加了live参数表示只导出存活对象文件会小不少但坏处是会触发一次Full GC。如果你的系统已经处于频繁Full GC的状态这一步可能让服务更卡。我这次是紧急处理能接受但如果系统完全没法动宁可别加live参数。导出期间应用会停顿最好选择业务低峰期操作。如果实在没办法也可以用jcmd GC.heap_dump相比之下和jmap差不多但功能更底层更稳定。导出的文件有3.7GB本地用MATEclipse Memory Analyzer打开之前一定要把MAT的内存调大。默认的eclipse.ini里-Xmx可能只有1GB打开这种文件直接报Java heap space需要改成-Xmx8g才行。如果不想导dump也可以用jmap先看一眼对象分布快速判断问题方向比dump轻量很多$ jmap -histo:live 21435 | head -30 num #instances #bytes class name ---------------------------------------------- 1: 1803364 1001079856 com.example.order.Order 2: 7213456 865614720 com.example.order.OrderItem 3: 12345678 524691315 [C 4: 987654 401237504 [B看到这个输出问题已经比较明显了Order对象有180万个实例占用约1GBOrderItem对象有721万个实例占用约865MB。这两个类加起来占了堆的一半以上而且它们都不是JDK内部类而是业务对象——这就是突破口。3.2 用MAT分析大对象从直方图到支配树打开hprof后我一般先看Histogram直方图确认哪些类型占用最大和jmap看到的一致。然后重点看Dominator Tree支配树它能呈现对象之间的持有关系告诉你“谁”是真正撑住整个内存的大头。这次支配树明显指向一个异常的持有链ThreadPoolExecutor$Worker (2个) -- java.util.concurrent.LinkedBlockingQueue -- LinkedBlockingQueue$Node -- com.example.order.export.ExportTask (约860,000个实例, retained heap ≈ 2.1GB) -- java.util.ArrayList -- com.example.order.Order (180万个实例) -- java.util.ArrayList -- com.example.order.OrderItem (721万个实例)也就是说一个LinkedBlockingQueue里塞了约86万个ExportTask对象每个Task里又带着一个包含Order和OrderItem的完整对象树总共占用了2.1GB的保留内存。看引用链这些Task被ThreadPoolExecutor$Worker持有着也就是在线程池的任务队列里排队等待执行但消费线程只有2个生产速度远高于消费速度任务越积越多最终把老年代直接塞满。用MAT里右键某个对象选择“Path to GC Roots”可以看到更具体的引用路径确认这些Task并不是临时状态而是被线程池长期持有。到这一步问题代码的轮廓已经出来了一个使用无界队列的线程池接收了大量携带重对象的生产任务消费不过来。3.3 顺着引用链到业务代码回看代码找到ExportTask的定义和提交逻辑问题立刻清楚了// 业务方法导出某个用户的全部历史订单 public void exportOrders(Long userId) { // 一次性把该用户所有历史订单全查出来 ListOrder orders orderService.listAllOrders(userId); // 把这一大坨数据封装成任务丢进线程池 exportExecutor.submit(new ExportTask(orders)); }问题根源有几个层次一个用户的全量历史订单可能包含几千甚至上万条ExportTask里直接持有整个ListOrder单个对象就很大大客户同时发起批量导出任务数量暴涨线程池队列是无界的任务只进不出内存无限增长老年代被占满后触发Full GC又因为任务都是存活的回收不掉形成一个恶性循环4. 根因落地线程池无界队列是如何拖垮JVM的4.1 问题代码还原与修复方案问题的核心不在JVM参数而在线程池设计。当时的线程池配置大概是这样的ExecutorService exportExecutor new ThreadPoolExecutor( 2, // 核心线程数 2, // 最大线程数 0L, TimeUnit.MILLISECONDS, new LinkedBlockingQueue() // 无界队列 );核心线程数2最大线程数2队列无界。当任务提交速度超过处理速度时新任务不会触发拒绝策略而是全部堆积在队列里。如果任务本身又是一坨大对象内存占用就会以非常快的速度膨胀。这个设计从内存安全角度讲几乎是“裸奔”的——没有任何机制能阻止队列无限增长。修复分两个层面。第一层是业务改造不能让一个任务承载全量数据// 分页拉取每页500条拆分任务 public void exportOrders(Long userId) { long pageSize 500; long total orderService.countOrders(userId); long pages (total pageSize - 1) / pageSize; for (int page 0; page pages; page) { ListOrder pageData orderService.listOrdersByPage(userId, page, pageSize); exportExecutor.submit(new ExportTask(pageData, page)); } }这样每个ExportTask最多持有一页数据500条订单记录单个任务的内存占用直降一个数量级。更重要的是如果总量很大但单页很小队列里即使堆积任务每个任务的“平均重量”也小得多。第二层是线程池改造必须使用有界队列并配置合理的拒绝策略ExecutorService exportExecutor new ThreadPoolExecutor( Runtime.getRuntime().availableProcessors(), // 核心线程CPU核数 Runtime.getRuntime().availableProcessors() * 2, // 最大线程2倍核数 60L, TimeUnit.SECONDS, new ArrayBlockingQueue(1000), // 有界队列最多1000个任务 new ThreadFactoryBuilder().setNameFormat(export-pool-%d).build(), new CallerRunsPolicy() // 队列满时由提交线程执行 );有界队列的意义在于一旦堆积超过1000个任务系统立刻感知压力触发拒绝策略而不是放任内存无限增长。这里选CallerRunsPolicy是因为它不会丢任务——队列满了之后由提交任务的线程比如Tomcat请求线程直接执行导出逻辑相当于把压力自然传导给上游起到削峰和限流的效果。相比AbortPolicy直接抛异常或者DiscardPolicy静默丢弃CallerRunsPolicy更稳妥。4.2 JVM参数与线程池参数一起调优代码修完之后JVM参数也要顺手调整。虽然根因不在参数但好的参数配置能让系统在遇到类似问题时更从容。修复前-Xms4g -Xmx4g -Xmn2g -XX:UseConcMarkSweepGC -XX:PrintGCDetails -XX:PrintGCDateStamps -Xloggc:/data/logs/gc.log修复后-Xms4g -Xmx4g -XX:UseG1GC -XX:MaxGCPauseMillis100 -XX:HeapDumpOnOutOfMemoryError -XX:HeapDumpPath/data/dump/ -XX:PrintGCDetails -XX:PrintGCDateStamps -Xloggc:/data/logs/gc.log几个调整的思考Xms和Xmx都设为4g避免JVM在运行期因为堆扩容、缩容产生额外停顿和不确定性从CMS切到G1倒不是说CMS不行而是在堆比较大、GC压力高的时候G1对内存碎片的容忍度更好Allocation Failure的触发频率会明显降低同时MaxGCPauseMillis100给了G1一个明确的暂停时间目标加上HeapDumpOnOutOfMemoryError这是所有生产服务都应该标配的参数一旦真正OOM会自动留下现场dump文件省去下一次靠运气抓堆的麻烦上线后验证效果也很直接压测时任务处理速度提升队列深度稳定在几十到几百的范围内不再无限增长连续观察一周Full GC从每小时200多次降到每天几次FGCT从574秒降到个位数P99延迟从3.8秒回到80毫秒上下。这次事故才算真正画上句号。5. 排查实录踩过的坑与工具速查5.1 最容易走偏的几个环节这次排查过程中我踩过或见过的坑不少都值得拿出来说一说免得你下次再走弯路。第一个坑是想当然地怀疑JVM参数。刚开始看到老年代99%占用我一度觉得是不是新生代太大导致对象过早晋升还想把-Xmn调小一点试试。后来结合GC日志看到回收前后老年代几乎没变化才意识到这不是晋升策略的问题而是老年代里的对象根本就没死。调参数前先看回收效果这是一条铁律。第二个坑是生产高峰期随意使用带live参数的jmap或jstat命令。jmap -dump:live会触发一次Full GC在系统已经很卡的情况下这一下可能直接把服务打成雪崩。如果业务不能接受停顿要么换用不带live的dump方式要么先用jmap -histo:live快速看个大概要么等到低峰期再做完整dump。我这次属于紧急情况事后想想其实有更稳妥的操作路径。第三个坑是只数Full GC次数不看单次耗时和回收后的内存差。一个系统如果Full GC次数多但每次只要几十毫秒、回收后内存明显下降说明GC在工作问题未必严重反过来像这次一样每次3秒多、回收等于没回收才是灾难。判断GC是否健康至少要看FGC、FGCT、O区变化这三个指标放在一起。第四个坑是排查前不看发布记录。其实如果早点把“订单批量导出”这个新功能纳入视野至少能提前一小时锁定方向。线上问题的黄金排查法则永远是先看变更再看指标最后才碰代码细节。5.2 工具速查表与核心心得把这次用到的排查工具和定位思路整理成一个速查表下次遇到类似问题可以直接照着过一遍。症状优先怀疑方向第一步操作FGC频繁且单次FGCT高老年代堆积大量存活对象jstat -gcutil pid 1000 5看O区变化和FGC趋势FGC频繁但单次耗时不高小对象频繁晋升、元数据膨胀看GC日志晋升情况调Survivor区大小或晋升阈值CPU高但GC正常业务线程死循环、锁竞争top -Hp pid找线程号再jstack看线程栈接口慢但JVM内存正常DB慢查询、下游依赖变慢先查APM链路和数据库监控别急着怀疑JVM常用命令备份jps -l定位Java进程jstat -gcutil pid 1000 5看GC趋势和内存区域使用率jmap -histo:live pid看对象数量与大小分布jmap -dump:live,formatb,filexxx.hprof pid导出堆转储jstack pid看线程栈配合top定位CPU热点jcmd GC.heap_dump -all xxx.hprof pidJDK自带另一种堆导出方式arthas的dashboard、heapdump、thread命令在线排查神器适合不想反复重启的场景最后再分享一个心得排查Full GC时我脑子里一直挂着的一句话是——“这些对象本来应该在什么时候死掉”所有的GC问题本质上都是对象生命周期被意外拉长了。循环引用的局部变量、没关闭的IO流、持有大对象的静态缓存、无界队列里的积压任务都是在阻止对象“按时死亡”。你只要顺着引用链找到那个不该存在的强引用问题就解决了。这次事故之后我把线程池队列深度监控也加上了。队列里积压多少任务是个比CPU和内存更早报警的指标。有时候问题还没把内存打满队列深度已经在疯狂上涨提前看到它就能在Full GC爆发之前把问题摁住。这个建议也推荐给你特别是手上有大量异步任务、导出导入、消息转储类业务的服务真的能救命。 
