记录在工业数字工厂项目中,一次周期性接口延迟的排查过程,涵盖问题发现、工具使用、根因分析和最终方案。
一、故障现象
1.1 背景
我所负责的凯士比数字工厂(KiPlant)是一个覆盖生产全流程的 SaaS 平台,基于 Spring Cloud Alibaba 构建。其中的 APS(高级计划排程)模块是核心功能之一——每天早晨工厂开工时,系统会根据订单、设备产能、物料库存等数据自动生成当天的生产排程计划。
1.2 问题表现
项目上线运行一段时间后,运维同事在 Grafana 监控面板上发现了一个规律性的异常:每天早上 8 点左右(工厂排产高峰期),APS 模块的接口 P99 响应时间从正常的 200ms 飙升到 2-3 秒。更关键的是,这个延迟不是持续的,而是呈现周期性的尖刺——大约每隔 5 分钟出现一次,每次持续 1-2 秒,然后恢复正常。
这直接影响了工厂调度员的使用体验,排产页面频繁出现"请求超时"的提示。
二、排查过程
2.1 第一步:排除常规嫌疑人
拿到问题后,我按照"自顶向下"的思路逐一排查:
排查数据库。 在 APM(应用性能监控)上检查了对应时间段的 SQL 耗时,数据库层面一切正常,没有慢查询。
排查网络。 检查了服务间的网络延迟和丢包率,也没有异常。
排查业务代码。 查看了错误日志,没有异常堆栈,只有大量的超时日志。
常规排查没有发现问题,但"周期性尖刺"这个特征给了我方向——这很像是 GC 停顿。
2.2 第二步:关联 JVM 监控
在 Grafana 上切换到 JVM 监控面板,将接口响应时间曲线和 GC 停顿时间曲线叠加显示。结果一目了然:每一个响应尖刺都精确对应一次 Full GC 停顿,停顿时间在 1.5-2 秒之间。
这基本确认了方向:是 Full GC 导致了 Stop-The-World(STW),所有业务线程在 GC 期间被暂停,接口请求无法处理。
2.3 第三步:深入 GC 日志分析
通过 jstat -gcutil <pid> 1000 持续观察 GC 状态,发现了以下规律:
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
0.00 45.21 78.33 89.72 94.11 91.23 156 3.212 12 21.456 24.668
0.00 45.21 82.15 92.18 94.11 91.23 157 3.245 12 21.456 24.701
...
0.00 0.00 12.33 34.56 94.11 91.23 158 3.312 13 23.012 26.324关键发现:Old 区(O 列)使用率增长非常快,Young GC 之后有大量存活对象晋升到 Old 区,导致 Old 区频繁被填满触发 Full GC。当时使用的是默认的 Parallel GC,Full GC 会对整个堆进行压缩整理,4G 的堆一次 Full GC 耗时 1.5 秒以上。
2.4 第四步:堆转储分析,找到"内存杀手"
使用以下命令导出堆快照:
jmap -dump:live,format=b,file=heap_dump_20231108.hprof <pid>用 Eclipse MAT(Memory Analyzer Tool)打开 hprof 文件,直接查看 Leak Suspects 报告。
MAT 明确指出:一个 com.kiplant.aps.engine.PlanningContext 类型的对象占据了 Old 区将近 60% 的空间。
2.5 第五步:代码定位根因
回到代码中查看 PlanningContext 的使用方式:
// 问题代码(简化后)
public class ApsEngine {
public PlanningResult schedule(FactoryId factoryId) {
// 每次排程都创建一个巨大的上下文对象
PlanningContext ctx = new PlanningContext();
// 加载全工厂数据:设备产能、物料库存、订单列表...
ctx.loadAllDeviceCapacity(factoryId); // ~500MB
ctx.loadAllMaterialStock(factoryId); // ~200MB
ctx.loadAllOrders(factoryId); // ~300MB
// 排列组合计算,耗时几十秒
return ctx.compute();
// 方法结束后 ctx 才能被 GC
}
}根因清晰了:
PlanningContext对象体积巨大(接近 1GB),远超 Young 区容量,JVM 直接将其分配到 Old 区。排程计算耗时几十秒,对象生命周期长,在计算完成前无法被回收。
早高峰多个排程任务并发执行,Old 区迅速被多个
PlanningContext占满,触发 Full GC。旧的
PlanningContext还没被回收,新的又被创建出来,形成恶性循环。
三、解决方案
问题明确后,我从 JVM 参数和代码两个层面进行了优化。
3.1 JVM 层面:从 Parallel GC 切换到 G1GC
Parallel GC 的 Full GC 是单次全堆压缩,堆越大停顿越长,不适合对延迟敏感的在线服务。G1GC 将堆划分为多个 Region,可以增量回收,并且通过 -XX:MaxGCPauseMillis 参数控制每次 GC 的停顿目标。
调整后的 JVM 参数:
# 堆内存从4G扩到8G,给排程引擎更多空间
-Xms8g -Xmx8g
# 切换到 G1GC
-XX:+UseG1GC
# 目标停顿时间200ms
-XX:MaxGCPauseMillis=200
# 增大 Young 区比例,让更多短生命周期对象在 Young 区回收
-XX:G1NewSizePercent=40
# Old 区使用率达到45%就开始并发标记,提前回收,避免 Full GC
-XX:InitiatingHeapOccupancyPercent=45为什么选 G1 而不是 ZGC? 当时的 JDK 版本是 11,ZGC 还处于实验阶段,G1 是生产环境中最成熟稳定的低延迟 GC。而且 G1 在中大堆(4G-16G)上表现优秀,适合我们的场景。
3.2 代码层面:治本之策
仅调 JVM 参数是治标不治本。真正的问题在于 PlanningContext 的使用方式。
优化一:对象池复用。 引入对象池,排程计算完成后清理内部数据放回池中,避免每次都分配巨大对象。
public class ApsEngine {
// 基于 Apache Commons Pool2 实现对象池
private final ObjectPool<PlanningContext> contextPool =
new GenericObjectPool<>(new PlanningContextFactory(), poolConfig());
public PlanningResult schedule(FactoryId factoryId) {
PlanningContext ctx = contextPool.borrowObject();
try {
ctx.loadData(factoryId);
return ctx.compute();
} finally {
ctx.clear(); // 清理内部数据
contextPool.returnObject(ctx); // 归还到池中
}
}
private GenericObjectPoolConfig<PlanningContext> poolConfig() {
var config = new GenericObjectPoolConfig<PlanningContext>();
config.setMaxTotal(3); // 最多3个排程任务并发
config.setMaxWaitMillis(5000);
return config;
}
}优化二:数据分批加载。 将一次性加载全量数据改为按车间/产线分批加载,降低单次内存峰值。
// 改造前:一次加载全工厂所有设备产能
ctx.loadAllDeviceCapacity(factoryId);
// 改造后:按产线分批加载
List<ProductionLine> lines = lineService.getLines(factoryId);
for (ProductionLine line : lines) {
ctx.loadLineCapacity(line.getId());
ctx.computeLine(line);
ctx.clearLineData(line.getId()); // 算完一条线就释放这条线的数据
}这样单次内存占用从接近 1GB 降到了 200MB 左右。
四、效果验证
优化上线后,持续观察了两周的监控数据:
早高峰时段的周期性延迟尖刺完全消失,工厂调度员反馈"系统不卡了"。
五、复盘与方法论沉淀
这次排查让我总结出一套 JVM 问题排查的标准流程,后来整理成了团队的 SOP 文档:
第一步:看监控。 将业务指标(RT、吞吐量)和 JVM 指标(GC 次数、GC 耗时、堆使用率)在同一时间轴上对齐,看是否有相关性。绝大多数 JVM 问题在这一步就能看出方向。
第二步:用 jstat 看 GC 趋势。 jstat -gcutil <pid> 1000 持续输出各区使用率,观察 Old 区增长速度、YGC 后是否有大量对象晋升。
第三步:用 jmap 导堆快照、MAT 分析。 找到占用内存最多的对象是谁,回到代码看它为什么这么大、为什么不被回收。
第四步:分层解决。 JVM 参数调优(GC 算法选择、堆大小、各区比例)解决当前问题;代码层面优化(对象复用、分批加载、减少大对象分配)解决根本问题。
最重要的一点:永远不要只调 JVM 参数就收工。 参数调优是止血,代码优化才是治病。如果代码本身存在大对象、内存泄漏等问题,再怎么调参也只是推迟问题爆发的时间。
如果这篇文章对你有帮助,欢迎访问我的博客 robinzhu.top 获取更多实战分享。