记一次诡异的频繁Full GC

报警了,系统异常飙升到3000+。经排查竟然是rpc接口超时了,但是服务提供方反馈系统1ms就返回了,为什么consumer端耗时是13000+ms,网络异常情况下的耗时也不可能这么长呀,不科学~瞅了一下机器监控,what,机器竟然一直都在full gc。立马去机器上查看情况:用户线程已全线暂停,gc线程cpu占用率居高不下,rpc线程池堵塞。那是什么导致的频繁的full gc呢?

GC日志

我们先去看看gc日志,看看是什么导致的频繁full gc:

2018-10-12T12:17:35.328+0800: [Full GC (Metadata GC Threshold) 2018-10-12T12:17:35.328+0800: [CMS2018-10-12T12:17:36.998+0800: [CMS-concurrent-mark: 1.617/1.682 secs] [Times: user=1.70 sys=0.01, real=1.69 secs] 
 (concurrent mode failure): 1080352K->1080354K(2355200K), 5.0626275 secs] 1081703K->1080354K(3737600K), [Metaspace: 206712K->206712K(1282048K)], 5.0640593 secs] [Times: user=5.09 sys=0.00, real=5.06 secs] 
2018-10-12T12:17:40.393+0800: [Full GC (Last ditch collection) 2018-10-12T12:17:40.393+0800: [CMS: 1080354K->1080354K(2355200K), 3.4270709 secs] 1080354K->1080354K(3737600K), [Metaspace: 206712K->206712K(1282048K)], 3.4283073 secs] [Times: user=3.33 sys=0.11, real=3.43 secs] 
2018-10-12T12:17:43.833+0800: [Full GC (Metadata GC Threshold) 2018-10-12T12:17:43.834+0800: [CMS: 1080354K->1080354K(2355200K), 3.4584908 secs] 1080361K->1080354K(3737600K), [Metaspace: 206712K->206712K(1282048K)], 3.4598680 secs] [Times: user=3.48 sys=0.00, real=3.46 secs]

从gc日志能够看出来,导致该full gc的原因是达到了metaspace的gc阈值,这里先解释下Metadata GC ThresholdLast ditch collection

  • Metadata GC Threshold:metaspace空间不能满足分配时触发,这个阶段不会清理软引用;
  • Last ditch collection:经过Metadata GC Threshold触发的full gc后还是不能满足条件,这个时候会触发再一次的gc cause为Last ditch collection的full gc,这次full gc会清理掉软引用。

看到这里大家可能会有疑问了,为啥你的gc日志打印了gc的原因呢?其实从jdk8开始,gc日志会默认打印gc cause,如果是jdk8之前的版本,可以通过JVM参数-XX:+PrintGCCause来打印gc cause。另外多嘴一句,观察gc日志其实可以发现大量的gc都是因为Allocation Failure触发的,大家不要以为这个不正常,其实大部分的gc都是因为内存分配失败触发的

言归正传,既然是metaspace区域使用达到gc阈值从而触发的full gc,那我们来看一下MetaspaceSize和MaxMetaspaceSize的设置值:都是256m,但从gc日志也可以看出来(206712K->206712K),发生full gc时metaspace才使用206m,并没有达到阈值呀,这就奇怪了,没有达到阈值为什么还触发了full gc呢?看了下JVM各个区域使用情况,发现metaspace committed内存达到262144k,大于gc的阈值256m,基本上到这里,也就明确原因了:metaspace的内存碎片化导致了该悲剧的诞生

导致Full GC的罪魁祸首

对于metaspace内存碎片化,有一个场景倒是可以满足,那就是创建了大量的classloader。目前就一次出现full gc时间点的heap dump不太能看出来问题,我通过增加jvm参数-XX:+HeapDumpBeforeFullGC-XX:+HeapDumpAfterFullGC分别在发生full gc前后做heap dump。通过对比分析full gc发生前后的heap dump,发现在full gc前创建了大量的sun.reflect.DelegatingClassLoader,full gc后该classloader也减少了约1000个。

到这里,导致该问题的罪魁祸首就找到了,那就是sun.reflect.DelegatingClassLoader,但是为什么类加载器过多就会导致内存碎片化呢?在类加载器第一次加载类的时候,都会在metaspace区域为其分配一块内存,并且每个类加载器的内存区域都是独立的,当然咯,一定要走出这个误区,类加载器的内存分配跟加载类的数量是没有关系的,即使类加载器只加载一个类,也是会在metaspace为其分配一块内存的。当出现频繁的类加载器创建的时候,这个时候就可能会出现metaspace内存使用率低,但是committed的内存已经达到了full gc的阈值从而触发了full gc。

写在最后的

一次简单的线上小问题分析,如果项目有大流量入口频繁使用反射就一定要注意了,警惕大流量带来的大量反射类加载器创建引发的频繁full gc。

推荐阅读更多精彩内容