记一次排查线上频繁FullGC 过程
一、一段艰辛的排查过程1.突发告警1.1 新生代老年代情况:1.2 老年代GC情况 2.紧急处理3.问题定位3.1 dump文件过大:3.2 如何分析:3.3 排查原因3.4 水落石出 4.修复上线 二、收获一、一段艰辛的排查过程
记录一次生产环境频繁FullGC的排查过程,艰辛但收获满满;
1.突发告警
这是一个风和日丽的下午,已经疲惫不堪的我正日常码代码,突然收到JVM监控告警,进入监控大盘查看JVM情况:
1.1 新生代老年代情况:
图片截了一张最简化的出来,因为公司数据安全限制;
蓝色:新生代
棕黄色:老年代
从图线中可以看出,新生代是在某一时刻突然被打满的,这种情况猜测可能是产生了死循环、批量导出等问题;
1.2 老年代GC情况
图线呈阶梯递增趋势,表明频繁 FullGC,但问题就在,频繁FullGC而GC不掉对象,说明这些对象还存在Roots;
2.紧急处理
在公司的一条军规:先恢复,再定位;先恢复服务的可用,再来定位问题的原因;
我的服务是多节点部署,通过公司网关做负载均衡:
周知 PM下线 XX节点;网关下线XX节点服务;生成dump文件 jmap -dump:live,format=b,file=dump.hprof 进程号;重启服务,恢复可用;
3.问题定位
登录服务器查看生成的 dump文件,大小有29G,面对的第一个问题来了;
3.1 dump文件过大:
分析dump文件,是需要内存来支撑的,而29G的内存就算拿到本地电脑也无法分析,所以我找运维同学申请了一台新服务器(130G内存),将29G的dump压缩,压缩zip包之后大概5G,发送到新服务器;
3.2 如何分析:
1.下载Linux版本的MAT
2.下载后解压,进到MAT目录中,执行:
修改MAT JVM参数
MemoryAnalyzer.ini 调整堆大小可以容纳你的dump文件的大小
./ParseHeapDump.sh jmap.info org.eclipse.mat.api:suspects org.eclipse.mat.api:overview org.eclipse.mat.api:top_components
3.上述命令我大概等了2个小时,生成了三个压缩包文件:
jmap_Leak_Suspects.zip
jmap_System_Overview.zip
jmap_Top_Components.zip
在生成报告的这2个小时的时间里,排查链路追踪日志、查看网关请求日志、都没有查到可疑问题;将所有的希望都寄托在了报告上;
3.3 排查原因
终于生成了报告:
报告中提示有一个问题,占用了23.4G内存,下面的问题怀疑也没有给也直接的原因,点击See stacktrace:
栈信息中可以看出,是调用系统中的一个Excel转PDF的工具导致的;aspose是一个专门做文档转换的一个工具
3.4 水落石出
既然是Excel转换PDF导致的,那就查下当前时间段系统中记录的上传日志,有一个时间点比较符合的Excel,拿到上传到OSS的链接,下载到本地(文件非秘密文档)跑单测,本地运行报OOM,果然是这个文件的问题;
原因:用户上传的Excel对多行整列加了底色,比如这种:
然后导致aspose解析时,认为有底色的列就有数据,造成一直FullGC;
4.修复上线
问题定位到了,和PM确认后,下线了Excel转换PDF的功能;
本来打算限制行和列的个数,后来看系统上传的Excel格式乱七八糟,竟然也有几万行的;
二、收获
我的系统上游对接了很多的业务系统,出现问题后收到各方反馈,一方面顶住压力,另一方面及时向各级领导反馈原因;
整个排查过程,艰辛,未接触过 JVM导致的生产问题,但整个过程下来,也学到了非常多的知识;也感谢同事的相助;