一次 JVM Full GC 排查全过程-编程实验室

一、问题背景

某天下午，运维收到生产环境告警：某业务系统的定时任务服务 CPU 使用率飙升至 90%+，服务响应变慢，部分定时任务执行超时。

告警信息： [ALERT] xxx-schedule 服务 CPU 使用率 92.3% [ALERT] xxx-schedule 服务 Full GC 次数: 15次/分钟 [ALERT] syncDataJob 执行超时，耗时: 180s

二、问题现象

2.1 GC 日志分析

登录服务器查看 GC 日志：

tail -100f /logs/xxx-schedule/gc.log

2026-01-11T14:32:15.234+0800: [Full GC (Ergonomics) [PSYoungGen: 87296K->0K(153088K)] [ParOldGen: 349568K->298456K(349696K)] 436864K->298456K(502784K), [Metaspace: 128456K->128456K(1169408K)], 2.3456789 secs] 2026-01-11T14:32:18.123+0800: [Full GC (Ergonomics) [PSYoungGen: 87296K->0K(153088K)] [ParOldGen: 348234K->301234K(349696K)] 435530K->301234K(502784K), [Metaspace: 128456K->128456K(1169408K)], 2.5678901 secs] 2026-01-11T14:32:21.456+0800: [Full GC (Ergonomics) [PSYoungGen: 87296K->0K(153088K)] [ParOldGen: 349012K->305678K(349696K)] 436308K->305678K(502784K), [Metaspace: 128456K->128456K(1169408K)], 2.7890123 secs]

关键发现：

Full GC 频繁触发，约 3 秒一次
老年代使用率持续在 85%+ (298456K/349696K)
每次 Full GC 后老年代释放空间有限，呈上涨趋势
GC 耗时较长（2.3s ~ 2.8s）

2.2 使用 jstat 观察

jstat -gcutil 1000 10

S0 S1 E O M CCS YGC YGCT FGC FGCT GCT 0.00 98.23 45.67 86.34 94.12 91.23 1234 12.345 156 312.456 324.801 0.00 0.00 78.90 87.56 94.12 91.23 1235 12.456 157 315.234 327.690 0.00 97.45 12.34 88.91 94.12 91.23 1236 12.567 158 318.012 330.579

分析：

O (老年代) 持续增长：86% → 87% → 88%
FGC 次数快速增加
FGCT (Full GC 总时间) 占 GCT 的 96%+

三、定位过程

3.1 Dump 堆内存

# 生成堆转储文件 jmap -dump:format=b,file=/tmp/heap_dump_20260111.hprof

# 或者使用 jcmd（推荐） jcmd GC.heap_dump /tmp/heap_dump_20260111.hprof

3.2 使用 MAT 分析

导入 Eclipse MAT (Memory Analyzer Tool) 分析：

Leak Suspects 报告：

Problem Suspect 1:

The thread "xxl-job, JobThread-15-1704960000000" keeps local variables with total size 156,789,456 bytes (45.2% of total heap). Keywords: java.util.ArrayList, java.util.HashMap

Dominator Tree 分析：

3.3 追踪到具体代码

通过 MAT 的 “Path to GC Roots” 功能，定位到内存持有路径：

Thread: xxl-job, JobThread-15-1704960000000

└── SyncDataJob.handler() └── dataList (ArrayList) └── HashMap (156MB) └── Order objects (300,000+ 条)

四、根因分析

4.1 问题代码定位

查看 SyncDataJob.java：

@XxlJob(“syncDataJob”) public ReturnT handler(){

log.info("数据同步Job开始执行"); Long minId = 0L; while (true) { // 问题1: 每次查询100条，但内存中累积了所有处理过的数据 List<Map<String, Object>> dataList = orderMapper.selectByPage(minId, BATCH_SIZE); if (CollectionUtils.isEmpty(dataList)) { break; } // 问题2: 循环内创建大量临时对象 for (Map<String, Object> data : dataList) { Map<String, Object> map = new HashMap<>(); // 每条记录创建新Map // ... 填充数据 List<Map<String, Object>> paramList = new ArrayList<>(); paramList.add(map); // 调用外部服务 externalService.process(paramList); } // 更新minId继续下一批 minId = dataList.stream() .map(d -> ((Number) d.get("id")).longValue()) .max(Long::compareTo) .orElse(minId); } return ReturnT.SUCCESS;

}

4.2 问题分析

问题一：MyBatis 查询返回 Map 类型触发自定义 TypeHandler

项目配置了全局 TypeHandler： mybatis.type-handlers-package=com.xxx.domain.typehandler
JsonTypeHandler 会拦截 Map 类型，尝试将每个列值反序列化：
@MappedJdbcTypes(JdbcType.VARCHAR) public class JsonTypeHandler extends BaseTypeHandler {
private Map<String,String> map = new TreeMap<>(); // 每次实例化都创建 @Override public Map getNullableResult(ResultSet resultSet, String s) throws SQLException { return this.toObject(resultSet.getString(s), map.getClass()); // 频繁创建TreeMap }
}
问题二：循环内频繁创建临时对象
每处理一条记录就创建：

1 个 HashMap (约 200 bytes)
1 个 ArrayList (约 88 bytes)
若干 String 对象

当数据量大时（如 30 万条），产生大量短生命周期对象，导致 Young GC 频繁，部分对象晋升到老年代。
问题三：数据量估算
– 查询符合条件的数据量 SELECT COUNT(1) FROM order_info WHERE status = 0; – 结果: 324,567 条
五、解决方案
5.1 修复 TypeHandler 冲突

5.2 优化内存使用

@XxlJob(“syncDataJob”) public ReturnT handler(){ log.info("数据同步Job开始执行"); Long minId = 0L; // 复用对象 Map<String, Object> map = new HashMap<>(16); List<Map<String, Object>> paramList = new ArrayList<>(1); while (true) { List<Map<String, Object>> dataList = orderMapper.selectByPage(minId, BATCH_SIZE); if (CollectionUtils.isEmpty(dataList)) { break; } for (Map<String, Object> data : dataList) { map.clear(); // 复用Map Long id = ((Number) data.get("id")).longValue(); minId = Math.max(minId, id); // 填充数据... map.put("orderId", data.get("orderId")); // ... paramList.clear(); paramList.add(map); externalService.process(paramList); } // 显式释放引用，帮助GC dataList.clear(); dataList = null; log.info("处理了一批数据，当前minId={}", minId); } return ReturnT.SUCCESS; }

5.3 JVM 参数调优

# 原参数 -Xms512m -Xmx512m -XX:+UseParallelGC # 优化后 -Xms1g -Xmx1g -XX:+UseG1GC -XX:MaxGCPauseMillis=200 -XX:G1HeapRegionSize=8m -XX:InitiatingHeapOccupancyPercent=45 -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/logs/xxx-schedule/

六、效果验证

6.1 修复后 GC 情况

jstat -gcutil 1000 10

S0 S1 E O M CCS YGC YGCT FGC FGCT GCT 0.00 45.23 23.45 34.56 92.34 89.12 234 4.567 2 0.234 4.801 0.00 0.00 56.78 34.78 92.34 89.12 235 4.678 2 0.234 4.912 0.00 43.21 12.34 35.12 92.34 89.12 236 4.789 2 0.234 5.023

对比：

七、经验总结

7.1 排查流程

告警触发 → GC日志分析 → jstat观察 → heap dump → MAT分析 → 代码定位 → 修复验证

7.2 常见 Full GC 原因