问题现象
Springboot后台服务在向MySQL数据库写入数据的过程中,出现数据写入耗时过长的现象。正常情况下,这批数据的写入操作不应超过20分钟,但实际耗时却达数小时之久。
问题排查
首先怀疑是mysql瓶颈,但在mysql命令行里用processlist命令检查,未发现长时间等待的SQL语句,表明MySQL本身并没有出现性能不足的问题。
mysql -uroot -p mydatabase
show processlist
然后查看java后台日志发现线程池里的线程执行速度非常缓慢,按线程号过滤日志发现负责写入此批数据的线程在7:53卡住,直到9:47才恢复:
进一步检查后,发现发现gc日志目录里有大小为182G的dump文件,这个文件是项目组之前在java启动命令里配置的jvm参数(-XX:+HeapDumpBeforeFullGC)自动导出的:
Heap dump到磁盘本身会带来一些开销,因此我们先去掉了这个jvm参数。但重跑发现数据插入速度依然缓慢。
继续查看gc.log日志文件,可以看到有不少full gc发生,每次full gc会导致jvm暂停10秒左右。而两次full gc之间的间隔从一开始的几十秒到最后的1秒越来越短(每次gc释放的内存越来越少),导致jvm绝大部分时间都在进行gc,效率非常低。
full gc多数是由于在内存里创建了大对象造成的,从日志里看到要更新的计划在内存里是用map对象表示的,这些map对象的key数量总和1000万~2000万之间,每个value占用内存估算超过1KB,总共需要的内存粗估约10GB~20GB。
写入这批数据时,服务器可用内存情况:
jmap统计的backend jvm内存占用情况,可以看到BucketValue和DateFlagDto这两个对象占用的内存很高,而它们就是准备插入数据库的数据:
改进方案
至此频繁full gc的原因基本搞清楚了,即要导入的数据占用内存过多,以至于jvm不得不通过full gc让出足够的空间,而实际让出的空间有限且很快被从磁盘加载的新数据占满,导致再次full gc发生,如此循环。
解决方案也很简单,将数据拆为更小的批写入,改进后每批数据占用的内存大约是之前的十分之一,保险起见每次提交数据库后显式释放内存。现场验证频繁Full GC问题得到解决。
请保留原始链接:https://bjzhanghao.com/p/3340