一场FullGC故障排查

简介: 本文记录了一次线上CPU使用率异常升至104%的排查过程。通过分析发现,问题根源为频繁Full GC导致CPU飙升,而机器内存监控未明显升高,易造成误判。进一步使用JProfiler分析JVM堆内存,定位到大对象(List<Map>)占用近900MB空间,源于将Excel数据加载至内存并结构化存储,导致内存膨胀。结合代码逻辑分析,提出“激进治疗”(数据存入Redis)与“保守治疗”(减少冗余字段)两类解决方案,并总结了从监控识别到根因定位的完整排查思路,强调应关注JVM而非仅机器层面监控,对类似性能问题具有较高参考价值。

一、问题发现与排查
1.1 找到问题原因
问题起因是我们收到了jdos的容器CPU告警,CPU使用率已经达到104%

观察该机器日志发现,此时有很多线程在执行跑批任务。正常来说,跑批任务是低CPU高内存型,所以此时考虑是FullGC引起的大量CPU占用(之前有类似情况,告知用户后重启应用后解决问题)。
通过泰山查看该机器内存使用情况:

可以看到CPU确实使用率偏高,但是内存使用率并不高,只有62%,属于正常范围内。
到这里其实就有点迷惑了,按道理来说此时内存应该已经打满才对。
后面根据其他指标,例如流量的突然进入也怀疑过是jsf接口被突然大量调用导致的cpu占满,所以内存使用率不高,不过后面都慢慢排除了。其实在这里就有点一筹莫展了,现象与猜测不符,只有CPU增长而没有内存增长,那么什么原因会导致单方面CPU增长?然后又朝这个方向排查了半天也都被否定了。
后面突然意识到,会不会是监控有“问题”?
换句话说应该是我们看到的监控有问题,这里的监控是机器的监控,而不是JVM的监控!
JVM的使用的CPU是在机器上能体现出来的,而JVM的堆内存高额使用之后在机器上体现的并不是很明显。
遂去sgm查看对应节点的jvm相关情况:

可以看到我们的堆内存老年代确实有过被打满然后又清理后的情况,查看此时的CPU使用情况也可以与GC时间对应上。
那么此时可以确定,是Full GC引起的问题。
1.2 找到FULL GC的原因
我们首先dump出了gc前后的堆内存快照,
然后使用JPofiler进行内存分析。(JProfiler是一款堆内存分析工具,可以直接连接线上jvm实时查看相关信息,也可以分析dump出来的堆内存快照,对某一时刻的堆内存情况进行分析)
首先将我们dump出来的文件解压,修改后缀名.bin,然后打开即可。(我们使用行云上自带的dump小工具,也可以自己去机器上通过命令手工dump文件)

首先选择Biggest Objects,查看当时堆内存中最大的几个对象。
从图中可以看出,四个List对象就占据了近900MB的内存,而我们刚刚看到堆内存最大也只有1.3GB,因此再加上其他的对象,很容易就会把老年代占满引发full gc的问题。

选择其中一个最大的对象作为我们要查看的对象
这个时候我们已经可以定位到对应的大内存对象对应的位置:

其实至此我们已经能够大概定位出问题所在,如果还是不确定的话,可以查看具体的对象信息,方法如下:

可以看到我们的大List对象,其实内部是很多个Map对象,而每个Map对象中又有很多键值对。
在这里也可以看到Map中的相关属性信息。
也可以在以下界面直接看到相关信息:

然后一路点下去就可以看到对应的属性。
至此,我们理论上已经找到了大对象在代码中的位置。
二、问题解决
2.1 找到大对象在代码中的位置与问题的根本原因
首先我们根据上述过程找到对应位置与逻辑
我们的项目中大概逻辑是这样的:

  1. 首先会解析用户上传的Excel样本,并将其加载到内存中作为一个List变量,即我们上述看到的变量。一个20w的样本,此时字段数量有a个,大概占用空间100mb左右。
  2. 然后遍历循环用户样本,根据用户样本中的数据,再增加一些额外的请求数据,根据此数据请求相关结果。此时字段数量有a+n个,占用空间已经在200mb左右。
  3. 循环完成后将此200mb的数据存入缓存。
  4. 开始生成excel,将200mb数据从缓存中取出,并根据之前记录的a个字段,取出初始的样本字段填充至excel。
    用流程图表示为:

结合一些具体排查问题的图片:

其中一个现象是每次gc后的最小内存正在逐步变大,对应上述步骤中第二步,内存正在逐步膨胀。
结论:
将用户上传的excel样本加载到内存中,并将其作为一个List>的结构存储起来,首先一个20mb的excel文件以此方式存储会膨胀占用120mb左右堆内存,此步骤会大量占用堆内存,并且因为任务逻辑原因,该大对象内存会在jvm中存在长达4-12小时之久,导致一但任务过多,jvm堆内存很容易被打满。
这里列举了为什么使用HashMap会导致内存膨胀,其主要原因是存储空间效率比较低:
一个Long对象占内存计算:在HashMap结构中,只有Key和Value所存放的两个长整型数据是有效数据,共16字节(2×8字节)。这两个长整型数据包装成java.lang.Long对象之后,就分别具有8字节的MarkWord、8字节的Klass指针,再加8字节存储数据的long值(一个包装对象占24字节)。
然后这2个Long对象组成Map.Entry之后,又多了16字节的对象头(8字节MarkWord+8字节Klass指针=16字节),然后一个8字节的next字段和4字节的int型的hash字段(8字节next指针+4字节hash字段+4字节填充=16字节),为了对齐,还必须添加4字节的空白填充,最后还有HashMap中对这个Entry的8字节的引用,这样增加两个长整型数字,实际耗费的内存为(Long(24byte)×2)+Entry(32byte)+HashMapRef(8byte)=88byte,空间效率为有效数据除以全部内存空间,即16字节/88字节=18%。
——《深入理解Java虚拟机》5.2.6
以下是刚上传的excel中dump出的堆内存对象,其占用的内存达到了128mb,而上传的excel实际只有17.11mb。

空间效率17.1mb/128mb≈13.4%
2.2 如何解决此问题
暂且不讨论上述流程是否合理,解决办法一般可以分为两类,一类是治本,即不把该对象放入jvm内存中,转而存入缓存中,不在内存中则大对象问题自然迎刃而解。另一类是治标,即缩小该大内存对象,在日常使用场景下使其一般不会触发频繁的full gc问题。
两种方式各有优劣:
2.2.1 激进治疗:不把他存入内存
解决逻辑也很简单,例如在加载数据时,将其按照样本加载数据一条一条存入redis缓存,然后我们只需要知道样本中有多少的数量,按照数量的先后顺序从缓存中取出数据,即可解决该问题。
优点:可以从根本上解决此问题,以后基本上不会存在该问题,数据量再大只需要添加相应的redis资源即可。
缺点:首先会增加许多redis缓存空间消耗,其次从显示考虑对于我们项目来说,此处代码古老且晦涩难懂,改动需要较大工作量与回归测试。

2.2.2 保守治疗:缩减其数据量
分析2.1的上述流程,首先第三步是完全没必要的,先存入缓存再取出,额外占用缓存空间。(猜测系历史问题,此处不再深究)。
其次是在第二步中,多出来的字段n,在请求结束后该字段就已经无用了,因此可以考虑在请求结束后删除无用字段。
此时也有两种解决方案,一种是只删除无用字段缩减其map大小,然后将其作为参数传递给生成excel使用;另一种方式是请求完成直接删除该map,然后在生成excel时再重新读取用户上传的excel样本。
优点:改动较小,不需要太复杂的回归测试
缺点:在极端大数据量情况下,仍有可能出现full gc的情况

具体实现方式就不展开了。
其中一种实现方式
//获取有用的字段
String[] colEnNames = (String[]) colNameMap.get(Constant.BATCH_COL_EN_NAMES);
List colList = Arrays.asList(colEnNames);
//去除无用的字段
param.keySet().removeIf(key -> !colList.contains(key));
三、拓展思考
首先本文中监控图是在复现当时场景时人为制造的gc常见。
在cpu使用率图中,大家可以观察到cpu使用率上升时间确实跟gc的时间相吻合,但是并没有出现当时场景中的104%的CPU使用率。

其实直接原因比较简单,就是因为系统虽然出现了full gc,但是并没有频繁出现。
小范围低频率的full gc不太会引起系统的cpu飙升,这也是我们所看到的现象。
那么当时的场景是什么原因呢?

我们上文提到过,我们在堆内存中的大对象是会随着任务的进行逐步膨胀的,那么当我们的任务足够多,时间足够长,就有可能导致每次full gc后可用空间变得越来越小,当可用空间小到一定程度之后就,每次full gc完成之后发现空间还是不够使用,就会触发下一次的gc,从而导致最终结果的频繁发生gc,引起cpu频率的飙升不下。
四、问题排查总结
● 当我们遇到线上cpu使用率过高的情况时,可以先查看是否是full gc引起的问题,注意要看的是jvm的监控,或者使用jstat相关命令查看。不要被机器内存监控所误导。
● 如果确定是gc引起的问题,可以通过JProfiler直连线上jvm或者使用dump保存堆快照后离线分析。
● 首先可以找到最大的对象,一般情况下是大对象引起的full gc。还有一种情况是,不像这么明显是四个大对象,也可能是比较均衡的十几个50mb的对象,具体情况还需要具体分析。
● 通过上述工具找到确定有问题的对象后找到其堆栈对应的代码位置,通过代码分析找到问题的具体原因,通过其他现象推演猜测是否正确,进而找到问题的真正原因。
● 根据问题的原因解决此问题。
当然,上述只是不算很复杂的排查情况,不同的系统肯定有不同的内存情况,我们应当具体问题具体分析,而从此次问题中可以学到的就是如果排查解决问题的思路。

相关文章
|
Kubernetes Cloud Native 应用服务中间件
【云原生】使用k8s创建nginx服务—通过ingress类型暴露
【云原生】使用k8s创建nginx服务—通过ingress类型暴露
531 0
|
Kubernetes Java Linux
Linux|操作系统|Error: Could not create the Java Virtual Machine 报错的解决思路
Linux|操作系统|Error: Could not create the Java Virtual Machine 报错的解决思路
4627 0
|
1月前
|
SQL 人工智能 前端开发
QoderWake 1.0 正式发布:从桌面里的 Agent,到工作现场的数字员工
QoderWake v1.0正式发布:企业级数字员工团队平台。支持“一句话建岗”,预置10类特训岗位;Waker常驻钉钉/飞书群,@即响应、自动协作、跨任务记忆;具备定时/事件/API多触发方式与统一任务看板;已沉淀27.6万条记忆、12.3万项技能,助力组织实现人机协同增效。
1075 3
|
7月前
|
SQL 关系型数据库 Java
吃透 Seata 分布式事务:原理拆解 + 生产级落地 + 全场景避坑实战
本文深度解析阿里开源分布式事务框架Seata:剖析TC/TM/RM三大角色与全局事务流程,详解AT(零侵入)、TCC(强控制)、SAGA(长事务)、XA(强一致)四大模式原理、适用场景及核心对比,并通过电商下单实战演示AT模式落地,最后系统梳理生产环境高可用、SQL限制、幂等处理、XID传播等全链路避坑指南。
1640 4
|
存储 关系型数据库 MySQL
1071 - Specified key was too long; max key length is 767 bytes
【2月更文挑战第5天】1071 - Specified key was too long; max key length is 767 bytes 问题处理
|
9月前
|
人工智能 数据处理 调度
智能体如何被统一管理?AI Agent 指挥官的底层逻辑
AI Agent指挥官是面向多智能体系统的统一调度中枢,通过目标拆解、动态分配、状态管控与闭环约束,解决协作失序、结果不可控等难题,提升自动化系统的稳定性、可解释性与可扩展性,正成为智能体规模化落地的关键基础设施。
681 8
|
9月前
|
人工智能 自然语言处理 监控
多智能体如何高效协作?AI Agent指挥官与AI调度官的实践方法
本文提出AI Agent“指挥官+调度官”协同治理机制,通过角色分离、统一调度与规则约束,解决多智能体系统中的任务冲突、资源争抢与决策分散问题,提升复杂场景下的可扩展性、稳定性与可解释性。
913 3
|
10月前
|
数据采集 Java 数据库连接
Spring Batch实战全解析:从入门到精通,搞定企业级批处理难题
本文全面介绍了SpringBatch框架在企业级批处理应用中的核心技术与实战方案。文章首先阐述了批处理的典型特征(无交互性、海量数据、可靠性等)和SpringBatch的核心优势(轻量化、可扩展、事务安全等),并通过对比其他批处理方案突出其适用性。随后详细解析了SpringBatch的核心架构,包括JobLauncher、Job、Step等组件的职责分工,以及批处理执行流程。
853 1
|
11月前
|
安全 算法 数据安全/隐私保护
屏幕拍照精准溯源:从“防不住”到“不敢泄”的震慑闭环是如何形成的?
屏幕拍照泄密频发,隐形水印技术以“无感嵌入、拍必留痕”破解防护难题。通过在显示画面中嵌入用户身份、设备信息等溯源数据,实现拍照即锁定责任人,构建“事前威慑、事中记录、事后追责”的全链路闭环,筑牢“不敢泄、不能泄、不想泄”安全防线。
990 7
屏幕拍照精准溯源:从“防不住”到“不敢泄”的震慑闭环是如何形成的?
|
应用服务中间件 Linux 测试技术
Tomcat启动错误:组件启动失败StandardEngine[Catalina].StandardHost[localhost].StandardContext[]
解决此类问题需要系统地排查和分析,有时候甚至需要根据应用的具体情况定制化解决方案。注意的是,如果问题涉及到复杂的应用逻辑或第三方库,那么可能需要深入到具体的应用代码和库文档中查找原因。最后,保持软件环境的更新也是预防这类问题的好习惯,因为新版本的软件通常会修复旧版本中的已知错误。
1324 12