记一次诡异的频繁Full GC

2019年6月13日 246次阅读 来源: miaoLoveCode

报警了，系统异常飙升到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 Threshold和Last 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。

    原文作者：miaoLoveCode
    原文地址: https://www.jianshu.com/p/f3fd1664f1ee
    本文转自网络文章，转载此文章仅为分享知识，如有侵权，请联系博主进行删除。
点赞