后台频繁Full GC导致进程卡住问题一例

问题现象

Springboot后台服务在向MySQL数据库写入数据的过程中,出现数据写入耗时过长的现象。正常情况下,这批数据的写入操作不应超过20分钟,但实际耗时却达数小时之久。

问题排查

首先怀疑是mysql瓶颈,但在mysql命令行里用processlist命令检查,未发现长时间等待的SQL语句,表明MySQL本身并没有出现性能不足的问题。

mysql -uroot -p mydatabase
show processlist

然后查看java后台日志发现线程池里的线程执行速度非常缓慢,按线程号过滤日志发现负责写入此批数据的线程在7:53卡住,直到9:47才恢复:

file

进一步检查后,发现发现gc日志目录里有大小为182G的dump文件,这个文件是项目组之前在java启动命令里配置的jvm参数(-XX:+HeapDumpBeforeFullGC)自动导出的:

file

Heap dump到磁盘本身会带来一些开销,因此我们先去掉了这个jvm参数。但重跑发现数据插入速度依然缓慢。

继续查看gc.log日志文件,可以看到有不少full gc发生,每次full gc会导致jvm暂停10秒左右。而两次full gc之间的间隔从一开始的几十秒到最后的1秒越来越短(每次gc释放的内存越来越少),导致jvm绝大部分时间都在进行gc,效率非常低。

file

full gc多数是由于在内存里创建了大对象造成的,从日志里看到要更新的计划在内存里是用map对象表示的,这些map对象的key数量总和1000万~2000万之间,每个value占用内存估算超过1KB,总共需要的内存粗估约10GB~20GB。

file

写入这批数据时,服务器可用内存情况:

file

jmap统计的backend jvm内存占用情况,可以看到BucketValue和DateFlagDto这两个对象占用的内存很高,而它们就是准备插入数据库的数据:

file

改进方案

至此频繁full gc的原因基本搞清楚了,即要导入的数据占用内存过多,以至于jvm不得不通过full gc让出足够的空间,而实际让出的空间有限且很快被从磁盘加载的新数据占满,导致再次full gc发生,如此循环。

解决方案也很简单,将数据拆为更小的批写入,改进后每批数据占用的内存大约是之前的十分之一,保险起见每次提交数据库后显式释放内存。现场验证频繁Full GC问题得到解决。