1. 现象
最近在查看线上gc日志时,发现有一个系统通过System.gc()调用而导致频繁Full GC。而且这个调用是周期性的(每隔一个小时),详细大家可以参看以下日志截图(图1):
图-1
2. 分析过程
从(图1)中,我们可以发现:
1. Full GC每隔一个小时被触发一次,而且FULL GC的原因是因为系统有地方显示的调用了System.gc()方法
2. 这个触发是周期性的。通过日志可以发现很明显,每隔一个小时就GC一次
3. 堆内存一切都正常,系统设置了2G的堆内存,老生代100M+远没有达到Gc的触发阈值
根据以上的分析,找问题的基本方向就比较直接: 系统的某个地方有人显式创建了一个线程调用了System.gc()方法,而这个很有可能是引入了三方JAR包或则是框架引起的。所以,立马就Google一把,通过关键字: 'Full GC', 'one hour', 'System.gc()'等信息,可以很容易的过滤出一些信息,如果你对系统代码很熟悉,基本就可以定位到问题的根源。 通过google,我们可以发现:如果系统中使用了JAVA RMI框架,那么它会引起 Full GC 并且频率默认刚刚好是一个小时。正好,我们系统由于要动态修改日志级别,使用了JAVA RMI框架。解决方法:
1. 可以设置 sun.rmi.dgc.client.gcInterval,sun.rmi.dgc.server.gcInterval -D变量修改这个间隔频率
2. -XX:-DisableExplicitGC 通过使用该JVM参数来禁止显式调用System.gc()
好了,分析到这里,我们似乎已经把问题解决了(确实,通过以上2点的修改,我们能解决这个问题)。
但是。。。。 作为一个码农,总觉得这种解决方法太肤浅了,根本就没有找到root cause,比如:
1. 这个参数'sun.rmi.dgc.client.gcInterval' 在哪里被用到了?
2. 这个定时每隔1小时调用一次的线程到底在哪里?是如何被创建的?我们怎么找到他?
如果就此把电脑合上,那我肯定会睡不着觉。。。
所以,我们继续哈。。。
由于和线程相关,所以,我们就先dump出当前JVM的线程堆栈:
DUMP出来的堆栈有几十个线程,没用工具,直接打开VScode浏览了几遍,发现有一个叫'GC Daemon'的线程疑点最大,我们来看一下它的堆栈(图2):
图-2
所以,我们需要查看sun.misc.GC类的源码,由于自带的JDK8没有这个包的源码,大家可以通过这里去下载OPENJDK的源代码,截取一段代码(图3):
图-3
果然,这里起了一个线程,然后线程里面有显式的调用System.gc()。这个类中,关键是一个阈值'latencyTarget' 它决定了gc的频率,所以,一定有一个地方设置了这个值,并且通过GC.create()方法创建了这个线程,我们得找出来。好,那么我们继续看线程堆栈,可以发现有个线程名'RMI RenewClean'跟GC有点关系(图4):
图-4
好,我们查看DGCClient中RenewCleanThread的源码(图-5),对就是这里:GC.requestLatency()这个方法调用,创建了图3的daemon线程(大家可以跟代码去看下最后调用到了GC.create()),而这个间隔值 'gcInterval' 正好取值自-D变量 ( 图6)'sun.rmi.dgc.client.gcInterval' (sun.rmi.dgc.server.gcInterval变量似乎没用到哈)
图-5
图-6
3. 结论
到此,我想我已经找出了问题的根源,解决方法可以通过适当的增大这个-D变量来防止频繁FULL GC。第二个选项(DisableExplicitGC),个人觉得处理比较粗暴,粒度太大。