记一次诡异的频繁Full GC

Posted 2023-05-15

参考技术A

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

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

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

看到这里大家可能会有疑问了，为啥你的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的内存碎片化导致了该悲剧的诞生 。

对于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。

记一次 CMS GC导致 FULL GC 时间开销很大的排查

记一次 CMS GC导致 FULL GC 时间开销很大的排查

• 背景
• 定位分析过程
• 第一次尝试解决方案
• CMS GC收集器分析
• • 了解CMS收集原理
  • 优缺点分析总结
• 分析根因
• 解决方案

背景

1. 服务接入注册中心后，就会有实例健康检查，通过ip+port的方式访问接口，检查实例是否健康，某日有个实例出现了告警。检查发现是当时接口超时异常了，触发告警。
2. 短暂的时间后，服务又正常恢复了，接口正常响应。观察日志没有异常问题。

定位分析过程

1. 这个健康接口是个简单的返回，没有经过DB、缓存等。所以超时问题出现在服务本身。
2. 查看CAT、机器基础监控，检查内存，CPU，GC等监控，发现FULL GC在这个时间点有个很长的耗时，环比其他时间都没有这个现象。
3. 定位是GC 导致 时间很长，服务暂停，导致接口超时。

第一次尝试解决方案

1. 分析：服务的JVM参数是 -xms2g -xmx5g
2. 考虑到FULL GC时间长，那应该是老年代需要回收的垃圾太多了，导致整个GC耗时长了，所以调整-xmx4g，缩小JVM的大小，老年代尽快完成FULl GC.
3. 效果不明显，还是会出现这个FULL GC耗时长，接口超时告警. 进一步分析JVM，服务使用的是CMS GC收集器，考虑这里有个STW的阶段可能是原因。

CMS GC收集器分析

了解CMS收集原理

CMS（Concurrent Mark Sweep）收集器是 HotSpot 虚拟机第一款真正意义上的并发收集器，多线程标记清除算法，它第一次实现了让垃圾收集线程与用户线程（基本上）同时工作。

从名字中的Mark Sweep这两个词可以看出，CMS 收集器是一种 “标记-清除”算法实现的。整个过程分为四个步骤：

1. 初始标记： 暂停所有的其他线程，并标记一下 GC Roots 能直接关联的对象，速度很快 ；
2. 并发标记： 同时开启 GC 和用户线程，用一个闭包结构去记录可达对象。但在这个阶段结束，这个闭包结构并不能保证包含当前所有的可达对象。因为用户线程可能会不断的更新引用域，所以 GC 线程无法保证可达性分析的实时性。所以这个算法里会跟踪记录这些发生引用更新的地方。
3. 重新标记： 需要暂停所有的工作线程，为了修正并发标记期间因为用户程序继续运行而导致标记产生变动的那一部分对象的标记记录。
4. 并发清除： 开启用户线程，同时 GC 线程开始对未标记的区域做清扫。

优缺点分析总结

它是一款优秀的垃圾收集器，主要优点：并发收集、低停顿。但是它有下面的缺点：

1. 无法处理浮动垃圾；
2. 回收算法-“标记-清除”算法会导致收集结束时会有大量空间碎片产生。

分析根因

1. 项目中大量使用了本地缓存，使用 guava cache 缓存了很多数据。
2. 对于CMS垃圾收集器，如果是大量本地缓存应用的话，重新标记阶段这个耗时就会较长，因为在并发阶段很容易有很多新对象进入缓存，从而重新标记阶段扫描很耗时，并且重新标记阶段是STW，暂停所有的工作线程。
3. 当刚好进行并发阶段，同时缓存正在重新加载刷新的时候，就好会出现这个问题。

解决方案

1. 缓存设计上，减少不必要的缓存，如一些冷数据不再缓存。
2. 开启-XX:CMSScavengeBeforeRemark，在重新标记阶段前进行一次YGC，有利于减少 Young Gen 对 Old Gen 的无效引用，从而减少重新标记阶段扫描GC Roots的开销。
3. 尝试使用G1垃圾收集器，通过-XX:MaxGCPauseMillis设置最大停顿时间，提高服务可用性。
4. 考虑团队用的JVM 收集器都是CMS，本次优化是减少缓存的使用，同时开启 -XX:CMSScavengeBeforeRemark

服务使用大量本地缓存，CMS GC收集器重新标记阶段导致STW时间很长。