事故背景
下午两点半左右,本地开发环境的 MES 辅助服务(app-assist)”挂了”——接口无响应、日志停更。但排查发现:进程根本没死,端口还在监听。它陷入的是一种比崩溃更迷惑的状态——假死。
这篇文章完整复盘这次诊断,并借机把涉及的 JVM 基础概念(堆、分代、GC、晋升、物化)融会贯通地讲一遍。读完你会发现,所有现象都能用同一套逻辑串起来。
现场勘查
疑点一:进程还活着
1 | netstat -ano | grep 8099 |
端口监听正常,进程存在。但应用日志停在 14:38:33,之后再无业务输出。
疑点二:日志里的”死前挣扎”
按时间线翻日志:
| 时间 | 现象 |
|---|---|
| 14:36:23 → 14:37:12 | 整整 50 秒日志空白(进程整体停顿) |
| 14:37:36 | HikariPool - Thread starvation or clock leap detected (delta=49s) |
| 14:37:17-47 | Eureka 注册中心心跳超时、SocketException |
| 14:38:22 | 最后一条业务 SQL:多级预警任务 getMultiLevelAlertList |
| 14:38:33 | 参数打完,再无结果输出 |
很多人会把 Eureka 报错当成原因去查注册中心——其实它是症状:进程停顿了 50 秒,心跳自然超时。真正的原因要让 JVM 自己交代。
决定性证据:jstat
1 | jstat -gcutil 15140 |
间隔几秒采样两次,FGC 计数从 347 → 404 → 414 → 435 → 508 持续暴涨——每秒 2~3 次 Full GC,累计耗时 368 秒。老年代(O 列)100% 满,降不下来。
定性:Full GC 死循环。CPU 全部耗在 GC 上,业务线程饿死——假死的本质。
老年代到底装了多少:jstat -gc
jstat -gcutil 只给百分比,要拿绝对值用 jstat -gc(单位 KB):
1 | jstat -gc 15140 |
OC(Old Capacity)= 349,696 KB ≈ 341.5MB 老年代总容量OU(Old Used)= 349,651.9 KB ≈ 341.46MB 已用——与容量只差 44KB,满到溢出- 顺带读出 Eden:
EC58880 KB ≈ 57.5MB,EU100% 满——新到的结果行还在要内存
这就是后文所有对账数字(341.46MB 已用、57.5MB Eden、341MB 老年代容量)的出处。
内存里装的是什么:jmap
1 | jmap -histo:live 15140 | head -25 |
538 万个 HashMap$Node。这是 MyBatis resultType="Map" 的典型特征——每一行查询结果装配成一个 HashMap,行里的每个字段是一对 key/value(内部就是 HashMap$Node)。
把 top5 对象字节数相加 ≈ 340.7MB,而 jstat -gc 给出的老年代已用是 341.46MB——两个数字几乎相等。也就是说老年代的每一寸都被这个在途查询结果集占据,连框架常驻对象的空间都被挤没了。
线程卡在哪:jstack
1 | jstack 15140 | grep -A15 'quartzScheduler_Worker-9' |
工作线程还卡在”收行”的过程中——结果集没装配完,已收到的几十万行 HashMap 全部挂在结果 List 上,对 GC 全部可达、全部活着。
根因
一条 SQL(四层 @rank 用户变量嵌套子查询,驱动表 3 万行)的物化结果集比整个堆(512MB)还大。物化过程中对象穿过分代机制全部晋升老年代,灌满后 Full GC 面对活对象无能为力,进程被 GC 锁死。
概念课:从事故学 JVM
堆是什么
Java 程序跑在 JVM 里,每个对象(字符串、Map、查询结果行)都要占内存。JVM 专门划一大块内存给对象用,叫堆(Heap)。堆不是无限大的——本例启动参数圈定约 512MB。
垃圾回收:闭馆查座
临时变量、处理完就扔的查询结果,用完之后程序再也不会碰——这是垃圾。清洁工就是 GC(Garbage Collector)。判断标准:从程序还在用的引用出发,”够得着”的对象是活的;够不着的是垃圾。就像闭馆后图书馆查座:从还开着的灯一路走过去,桌上还有人的书不能动,其他全收走。
为什么分新生代/老年代
工程师观察到(弱分代假说):绝大多数对象朝生夕死;真正长寿的对象一旦活下来往往活很久。既然寿命差异巨大,混在一起打扫就亏了:
| 区域 | 类比 | 住着谁 | 打扫方式 |
|---|---|---|---|
| 新生代(Eden + 两个 Survivor) | 车间工作台 | 刚造出来的对象 | Minor GC:很快,大部分直接扔 |
| 老年代 | 仓库 | 熬过多次清扫的对象 | Full GC:全堆盘点,慢得多 |
打扫流程:新对象在 Eden(本例 57.5MB)出生 → Eden 满 → Minor GC:活对象搬 Survivor(各 54MB),死了的直接扔 → 反复存活的对象”变老”,晋升(promotion)进老年代 → 老年代满 → Full GC。
关键机制:GC 干活时所有业务线程暂停(Stop The World)。Minor GC 暂停几毫秒无感;Full GC 一停几百毫秒到几秒。Full GC 连打 = 服务假死。
物化是什么
数据本身躺在数据库里,不占 Java 一字节。查询时有两种消费方式:
1 | 流式:来一行 → 处理一行 → 扔一行。任何时刻内存里只有 1 行。 |
物化是常态,但要付”房租”:装配完成之前,物化出来的每个对象都是活对象。这次事故就是物化的结果集大到堆装不下它”活着的那段时间”。
事故重演(概念全串起来)
- 14:38:22 多级预警查询发起,MyBatis 开始物化:每收一行装配一个 HashMap 挂进 List;
- 对象死不掉:线程还卡在收行,List 上几十万个 HashMap 全部可达——分代机制的赌注(”多数对象是垃圾”)破产;
- Eden 57.5MB 反复填满 → Minor GC → 活对象整批晋升:Survivor 54MB 装不下几百 MB 活对象,57.5MB × 6 次 ≈ 345MB,正好灌满 341MB 老年代(
jstat -gc的OC=349,696KB); - Full GC 清不出任何东西:结果集依然可达(
jmap -histo:live强制 Full GC 后 538 万个 Node 依然存活,铁证)→ 释放 ≈ 0 → Allocation Failure 立刻再触发 → 每秒 2~3 次连打; - 每次 Full GC 都 Stop The World → 业务线程抢不到 CPU → 日志停更、心跳超时、接口无响应——但进程活着,端口在监听:假死。
一句话:
分代回收赌”对象朝生夕死”,而物化中的大结果集偏偏”又大又长时间活着”,于是穿过新生代、灌满老年代,Full GC 面对活对象无能为力,进程被 GC 锁死。
处置与预防
当场恢复:taskkill /F /PID 15140 重启(假死无法自愈)。
治本:
- 启动加大堆(
-Xmx1g)——512MB 跑全量 quartz 任务偏小; - 优化那条 SQL:四层
@rank用户变量嵌套在数据量增长后结果集会爆炸,改窗口函数或加内层过滤/限批; - 代码层面:大结果集查询设 limit、分批、或流式消费——别让单条 SQL 的结果集有机会和堆比大小。
排查速查卡
服务”没响应但进程还在” → 先想 Full GC 死循环:
1 | jps -l # 找到 PID |
四条命令,五分钟定性。