记一次艰难的GC问题排查！

记一次艰难的GC问题排查！

背景

gc问题一直是一个很难排查的问题，但是他又是一个经常在我们开发业务中出现的。这不，最近在我的项目中就出现了一个比较奇葩的gc问题，排查过程比较繁琐，所以在这里分享一下这个整个排查过程，希望对大家有一定的帮助

排查过程

确定GC出问题

在某一天的上午突然出现了报警，发现是ZK断开了链接，

从图上看我们这个错误是间断性的出现，最开始以为是zk出现了问题，后来经过排查其他服务的zk并没有出现任何问题。所以就怀疑是内部的代码出现问题导致的，研究之后发现是zk出现了心跳超时情况才导致的断开链接，所以就怀疑了两种情况：

网络有抖动机器间歇性卡死

如果网络有抖动的话的确是会出现偶发性超时，但是很明显，其他所有的服务都没问题，应该不是抖动导致。所以机器应该是间歇性的一个卡死，一般出现这个情况首当其冲的就是我们CPU被打满了，导致机器卡死，发现CPU并无问题，然后就是我们的gc带来的STW,会导致我们的jvm进程卡顿。

观察之后的确是young gc很慢，导致我们的JVM发生了GC卡顿，所以出现了这个现象。

排查原因

GC出现问题一般来说两大法宝可以解决大部分问题：

GC日志dump文件

出现问题之后我立马打开了GC日志，截图如下：

可以发现我们的young gc已经达到2.7s了，大家知道我们的young gc是全程STW的，那就意味着每次gc就会卡顿2.7s，那么zk超时断开链接也就符合正常了。再看了下这个gc收集情况，每次也能完全收集。在日志中很明显在root scanning的时间比较长，当时对这个阶段不太熟悉(后面会继续讲)，所以一直也不明白为什么这样，在网上各种搜索，也没有结论。

看完这两个文章之后，我突然想到了我们的代码也是counted loop的形式，所以就怀疑有可能也是这个问题导致的，马上进行代码优化，将for(int i = 0; i< n; i++) 中的int 换成了long，就可以避免这种jit的优化，马上兴冲冲的将其上线，结果过了一天之后依然存在这个问题，此时人都快崩溃，搞了半天原来不是这个问题导致的。

定位问题

对于G1之前只是看了些原理相关的，但是此时原理相关的东西好像在这里基本没啥用，所以我决定系统性的学习一下，这里我选择的是《jvm G1源码分析和调优》这本书，在读到5.4节的时候：

发现有两个之前没有见过的参数，一个是G1LogLevel,一个是UnlockExperimentalVMOptions，从解释说明上来看配置了之后能获取到更加详细的YGC日志，于是加上了这个参数然后继续观察，日志格式太长，只截取了部分日志信息，有兴趣的可以下来自己打印一下：

可以发现在SystemDictionary Roots阶段是比较慢的，但是这个又是啥玩意呢?在书里面是没有任何介绍的，于是又进行大量谷歌，终于是找到了一篇你假笨写的一篇文章：JVM源码分析之自定义类加载器如何拉长YGC，强烈推荐大家读完这篇文章。

好了最后我来盘一盘到底为什么会出现gc慢的问题呢?我们这个定时任务是一个定时查询微信退款信息的，微信的退款信息需要解析XML,就有如下代码:

而我们的罪魁祸首其实就在这个new XStream这个方法中，我们的默认构造方法会调用下面的这个构造方法：

需要注意的是我们每次创建一个XStream都会新创建一个ClassLoader，先解释一下ClassLoader，这里直接引用你假笨的一段话：

这里着重要说的两个概念是初始类加载器和定义类加载器。举个栗子说吧，AClassLoader->BClassLoader->CClassLoader，表示AClassLoader在加载类的时候会委托BClassLoader类加载器来加载，BClassLoader加载类的时候会委托CClassLoader来加载，假如我们使用AClassLoader来加载X这个类，而X这个类最终是被CClassLoader来加载的，那么我们称CClassLoader为X类的定义类加载器，而AClassLoader为X类的初始类加载器，JVM在加载某个类的时候对AClassLoader和CClassLoader进行记录，记录的数据结构是一个叫做SystemDictionary的hashtable，其key是根据ClassLoader对象和类名算出来的hash值(其实是一个entry，可以根据这个hash值找到具体的index位置，然后构建一个包含kalssName和classloader对象的entry放到map里)，而value是真正的由定义类加载器加载的Klass对象，因为初始类加载器和定义类加载器是不同的classloader，因此算出来的hash值也是不同的，因此在SystemDictionary里会有多项值的value都是指向同一个Klass对象。

我们把这个放到我们的场景来看就是下面这个情况：

由于我们每次请求都会新创建一个Xstream对象，从而也会新创建一个ClassLoader，由于我们的ClassLoader的key是根据每个对象来算出来的hash值，如果每次都新创建，自然hash值不一样，从而导致我们有很多ClassLoader指向XStream这个class。为什么SystemDictionary的大小会影响我们GC时间呢?

想象一下这么个情况，我们加载了一个类，然后构建了一个对象(这个对象在eden里构建)当一个属性设置到这个类(static变量)里，如果gc发生的时候，这个对象是不是要被找出来标活才行，那么自然而然我们加载的类肯定是我们一项重要的gc root，这样SystemDictionary就成为了gc过程中的被扫描对象了。

我们的class信息是被分配在哪里的呢?在java7的话是在永久代，在java8就来到了元数据空间也就是我们的堆上，所以我们的young gc的时候是不会回收我们的class信息的，那么我们怎么解决这个问题呢?

java7: 在G1垃圾收集器中，只有在进行full GC的时候，永久代才会被回收，这一过程是stop-the-world的。当不做Full GC的时候，G1运行是最优化的。只有当永久代满了或者应用分配内存的速度超过了G1回收垃圾的速度的时候，G1才会触发Full GC。在CMS垃圾收集器中，我们可以使用-XX:+CMSClassUnloadingEnabled在CMS concurrent cycle中回收集永久代。在G1里面没有对应的设置。G1只有在stop-the-world的Full GC的时候，才会回收永久代。我们可以根据应用的需要，设置PermSize和MaxPermSize参数来调优永久代的大小。java8：提供了四个参数-XX:MetaspaceSize，-XX:MaxMetaspaceSize，-XX:MinMetaspaceFreeRatio，-XX:MaxMetaspaceFreeRatio用来控制元空间的大小，当超过比例或者大小的时候就会进行收集。

但是我们这个问题不应该通过垃圾收集去解决，而是应该从根源上去解决，那就是不能使用默认的XStream构造函数,而是需要使用固定ClassLoader的构造函数。

经过修改之后上线，经过观察，没有出现慢GC的现象。

最后

经过这次排查的经验来看，遇到GC问题尤其是那种比较不常见的，真的是非常难搞，你可能需要对这个问题进行系统的学习，以及大量的查找资料才能找到原因，我在排查这个问题的时候掉了不少头发。在这里记录一下这个经验，希望对大家以后的一些排查能有帮助。