1.现象

在某个阳光明媚的中午（也有一说是下午），王童鞋急冲冲地跑过来，反馈了一个问题，就是每次点下页面的某个查询按钮，总是固定的等待很久的时间服务器没相应，而且其他功能还伴随间歇性的有卡顿现象。他反馈说，有可能是Mysql的问题导致的。并且还把监控的截图发给笔者看了下：

服务间歇性停顿问题优化｜得物技术

当然，这里显示的是Mysql的获取连接的时间，一直在递增，到了30号，基本上一次需要快2秒钟了。

OK，于是第一时间去阿里云RDS上面查看了数据库使用情况。

服务器支持的连接数情况：使用率才10%不到
这个是数据库的机器指标，基本指标都很平稳，值都不是很高

服务间歇性停顿问题优化｜得物技术

全部指标翻了一遍，没发现什么问题，并且看起来数据库都没啥压力。看来这个有可能不是数据库的问题， 这个Mysql获取连接慢，也许是现象，而不是原因。

2.现场排查

2.1 寻找线索

话说回来，每次排查线上问题的时候，都像破案一样，一方面需要保留现场痕迹，另一方面也需要寻找其他的各种蛛丝马迹。所以这里一边让王童鞋把JVM的堆栈等信息给dump出来（当然，为了不影响线上环境使用，数据dump出来之后，王童鞋也重启了机器），笔者一边继续翻日志&监控。

当查看了JVM信息之后，元凶的尾巴被揪出来了一些：

服务间歇性停顿问题优化｜得物技术

Pause Durations表示的是暂停时间，也就是JVM里面的STW(Stop The World)时间。图表里面avg/max end of minor GC (G1 Evacuation Pause)这个代表的是G1里面的young-gc。此刻，我们知道G1里面的YGC有问题，但是还不够，因为我们需要知道具体问题点在哪呢？又是什么原因导致的呢？

2.2 G1的young-gc简介

2.2.1 简介

作为CMS替代品的G1，一直吸引着众多Java开发者的目光。G1的目标是在满足期望的停顿时间的同时保存高吞吐量，适用于多核、大内存的系统。

在分配内存的时候，如果剩余的空间不能满足要分配的对象的时候，就会优先触发新生代回收，即young-gc(YGC)。G1中的YGC触发时，会一次性回收全部的新生代内存以及空的大对象区（前提是分区没有RSet引用）。目前比较新的垃圾收集器例如ZGC、Shenandoah都被称之为低延迟垃圾收集器，其目标是在任意内存下，保证停顿时间都保持在十毫秒以内。可见低延迟在垃圾收集器中的重要性。但是在G1中的YGC，它全部过程都是处于STW的，也就是说YGC的过程中，服务器是处于停顿状态中的。这也就解释了为什么Mysql获取连接超时他其实是现象而不是原因，因为不单单是Mysql获取连接， 在YGC的时候，除了 GC 线程之外整个服务器的所有Mutator线程( Java 应用线程)都停止了 ，服务卡顿便如此由来。

现在，通过监控知道了服务器慢，是因为YGC导致的，但是YGC的过程比较多，具体慢在哪，还是不得而知，问题如果想解决，还需要继续排查。

2.2.2 YGC过程图解

首先，在这里画一张图讲下G1的YGC的过程：

服务间歇性停顿问题优化｜得物技术

通过上面的图例也看到了，一次YGC过程还是有挺多操作的，那么YGC具体慢在哪些点呢？单凭监控还是不能找到元凶的，接下来还需要一些更有力的信息才能继续调查下去，这就是前面Dump出来的堆内存以及服务器中打印的GC日志。

2.3 重要线索

2.3.1 GC日志

接下来切到机器中，查看最近几次的日志。

服务间歇性停顿问题优化｜得物技术

总共花了0.4573432秒，共8核并行执行。仔细，看这些数据，发现有一处很不合理，就是上面红色的那一行字。 Ext Root Scanning堆外部根扫描，总共花了596ms，其中最高448ms ，要知道这次ygc也才花457ms，几乎把所有时间都花在这个Ext Root Scanning。

2.3.2 堆分析

下面是当时dump出来的堆里面发现的不正常对象：

服务间歇性停顿问题优化｜得物技术

这里可看到堆里面这个CompositeClassLoader这个类的对象偏多。要知道类加载器在系统中负责对类进行加载，通过传入一个类的全限定名称返回一个唯一的确定的类实例。这实属不正常。通过其包名字得知是xstream下面的(xstream是用于处理XML文件的序列化以及反序列化等操作)。

于是查阅xstream的主要的类
com.thoughtworks.xstream.XStream#XStream源码：

public XStream(ReflectionProvider reflectionProvider, Mapper mapper, HierarchicalStreamDriver driver) {

    this(reflectionProvider, driver, new CompositeClassLoader(), mapper);

}

这里是服务区里面创建的代码：

public static XStream createNew() {

        XStream xStream = new XStream(new Xpp3Driver(new NoNameCoder())) {

            @Override

            protected MapperWrapper wrapMapper(MapperWrapper next) {

                return new MapperWrapper(next) {

                    ....省去一些无用的代码

                    }

                };

            }

        };

            ...省去一些无用的代码

        return xStream;

    }

可以看到每次使用XStream都会创建一个XStream实例，而每个XStream实例都会创建一个CompositeClassLoader的类加载器。而CompositeClassLoader往往都是属于重量级的类，要知道系统自带的AppClassLoader以及ExtClassLoader还有BootstrapClassLoader统统都是单例的！所以这里明显会重复创建不必要的CompositeClassLoader。 到这里，基本已经确定元凶了 。

2.4 破案

接下来重新添加一个方法，把上面的多例改成按照每个类型创建一个单独的XStream对象，并在服务器中缓存，防止每次请求都创建一个单独的XStream实例：

    /**

     * @Description 为每次调用复用XStream

     */

    public static XStream getInstance(Class<?> clazz, String driverType) {

        return allXStream.computeIfAbsent(clazz, (k) -> {

            return createNew(driverType);

        });

    }

代码改完之后，再发布到生产线之后观察结果：

服务间歇性停顿问题优化｜得物技术

可以看到YGC的时间从1.5秒大幅度减少到平均10来毫秒左右，问题消失。

3.问题复现

因为目前看下来是XStream导致的YGC慢。但是如果想找到问题的源头，这里需要写几个Demo，抽丝剥茧，看看现场是否能复现出来，以便找出幕后的真正原因。

3.1 编写Demo

既然现在已经找到是XStream的问题了。那么接下来，开个新项目，写下如下代码，用于复现线上问题：

    public static void main(String[] args) {

        while (true) {

            new XStream();

        }

    }

输入JVM参数，然后执行：

-XX:+UseG1GC

-XX:+PrintGCDetails

-XX:+UnlockExperimentalVMOptions

-Xms2g

-Xmx2g

-XX:G1NewSizePercent=40

观察下日志：果然问题复现了。

服务间歇性停顿问题优化｜得物技术

并且通过对比2次YGC留下的存活对象发现：下面这些对象一直在增加(红色部分是增加的)。也就是说虽然这些对象是无法直接使用的，但是因为被Root引用了，变成可达对象，无法在YGC回收。

服务间歇性停顿问题优化｜得物技术

3.2 更准确一点的Demo

如果看上面的日志，发现在Object Copy比较高。是因为前面的Demo写的比较暴力，就光new这些有问题的对象导致数据在Copy上花了大量的时间，所以这里Demo做少量修改，改成下面这个样子：

public static void main(String[] args) {

    prepare();

    System.out.println("准备完毕!可以观察YGC日志");

    ygc();

}




private static void prepare() {

    // 好一点的机器可以把这个1000 * 30调高一点来拖慢YGC时间

    for (int i = 0; i < 1000 * 30; i++) {

        new XStream();

    }

}




private static void ygc() {

    while (true) {

        byte[] ignored = new byte[1024 * 100];

    }

}

多执行几次YGC，然后再观察日志：

服务间歇性停顿问题优化｜得物技术

这样就更加符合线上的真实环境了。

3.3 再准确一点的Demo

从源码里面看到了，其实是XStream里面创建的CompositeClassLoader太多导致的问题，那么可以把prepare方法改成下面这个样子：

     private static void prepare() {

        for (int i = 0; i < 1000 * 30 * 20; i++) {

            new CompositeClassLoader();

        }

    }

然后再执行， 可是发现这代码执行之后，问题并没有解决 复现。但是类加载器的作用不就是为了加载类么？于是把代码改成这个样子：

    private static void prepare() {

        // 这里如果如果加载的类太少，这个问题复现不了。所以这里进行放大20倍处理

        // 其实这个20不准，其实值是40！

        // 也就是说额外创建一个XStream会触发40次多余的类加载动作

        for (int i = 0; i < 1000 * 30 * 20; i++) {

            CompositeClassLoader compositeClassLoader = new CompositeClassLoader();

            try {

                Class.forName("com.thoughtworks.xstream.mapper.EnumMapper", true, compositeClassLoader);

            } catch (ClassNotFoundException ignored) {




            }

        }

    }

再观察结果，问题复现！

服务间歇性停顿问题优化｜得物技术

如果只是JDK层面的话，问题基本上已经解决了，也不需要再继续调查下去了。但是本着一个程序员的与生俱来的刨根问底的这么一个特性，这个话题其实还没有完呢。因为这里还有些问题没有调查清楚：

1:为啥类加载器加载的类偏多的情况下啊，YGC的根扫描时间会偏久？

2:说到底，这个创建的XStream和CompositeClassLoader只是一个局部变量而已，为什么会是不可达对象，导致在YGC不能正常回收呢？

目前为止，要想知道答案，仅仅只看JDK的源码是肯定解决不了问题的。想要知道的更多，需要从HotSpot源码入手，继续探索！

4.一追到底

4.1 入口 G1RootProcessor::evacuate_roots

搜索OpenJDK的源代码，找到G1目录
hotspot/src/share/vm/gc_implementation/g1下面和根扫描有关的地方,找到G1RootProcessor.cpp文件下面的evacuate_roots方法(文章篇幅有限，所以只展示部分代码，有兴趣的可以自己去下载源码仔细看看)：

void G1RootProcessor::evacuate_roots(OopClosure* scan_non_heap_roots,

                                     OopClosure* scan_non_heap_weak_roots,

                                     CLDClosure* scan_strong_clds,

                                     CLDClosure* scan_weak_clds,

                                     bool trace_metadata,

                                     uint worker_i) {

  // 开始时间

  double ext_roots_start = os::elapsedTime();

  G1GCPhaseTimes* phase_times = _g1h->g1_policy()->phase_times();




  // 省去一些代码

  // 处理java根

  process_java_roots(strong_roots,

                     trace_metadata ? scan_strong_clds : NULL,

                     scan_strong_clds,

                     trace_metadata ? NULL : scan_weak_clds,

                     &root_code_blobs,

                     phase_times,

                     worker_i);




  if (trace_metadata) {

    worker_has_discovered_all_strong_classes();

  }




  // 处理VM根和stringTable下面的根

  process_vm_roots(strong_roots, weak_roots, phase_times, worker_i);

  process_string_table_roots(weak_roots, phase_times, worker_i);

  {

    G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::CMRefRoots, worker_i);

    if (!_process_strong_tasks.is_task_claimed(G1RP_PS_refProcessor_oops_do)) {

      _g1h->ref_processor_cm()->weak_oops_do(&buf_scan_non_heap_roots);

    }

  }

  // 省去一些代码

  // 等待执行结束

  _process_strong_tasks.all_tasks_completed();

}

其实这里面主要处理的就2种类型的根：

Java根：主要指类加载器和线程栈(见方法：process_java_roots)。
- 类加载器根(CLDGRoots)主要遍历它所引用的存活的Klass(对应java的class对象)并复制到其他区
- 线程栈根(ThreadRoots)包含java栈和本地栈涉及的局部变量等

JVM根：通常是一些全局的static修饰的C、C++变量(见方法：process_vm_roots)
- hotspot虚拟机需要保存的一些全局的变量。其中包括:JNIHandles,ObjectSynchronizer,SystemDictionary,StringTables,Jvmti等

2.GC需要处理的步骤清单 G1GCPhaseTimes::G1GCPhaseTimes

再继续查找代码发现：G1GCPhaseTimes.cpp文件下的G1GCPhaseTimes方法里面都是需要处理的步骤，其中包括扫描的根的类型集合，下面这些也会在日志中打印执行时间：

G1GCPhaseTimes::G1GCPhaseTimes(uint max_gc_threads) :

_max_gc_threads(max_gc_threads)

{

  _gc_par_phases[GCWorkerStart] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Start (ms)", false, G1Log::LevelFiner, 2);

  _gc_par_phases[ExtRootScan] = new WorkerDataArray<double>(max_gc_threads, "Ext Root Scanning (ms)", true, G1Log::LevelFiner, 2);




  _gc_par_phases[ThreadRoots] = new WorkerDataArray<double>(max_gc_threads, "Thread Roots (ms)", true, G1Log::LevelFinest, 3);

  _gc_par_phases[StringTableRoots] = new WorkerDataArray<double>(max_gc_threads, "StringTable Roots (ms)", true, G1Log::LevelFinest, 3);

  _gc_par_phases[UniverseRoots] = new WorkerDataArray<double>(max_gc_threads, "Universe Roots (ms)", true, G1Log::LevelFinest, 3);

  _gc_par_phases[JNIRoots] = new WorkerDataArray<double>(max_gc_threads, "JNI Handles Roots (ms)", true, G1Log::LevelFinest, 3);

  _gc_par_phases[ObjectSynchronizerRoots] = new WorkerDataArray<double>(max_gc_threads, "ObjectSynchronizer Roots (ms)", true, G1Log::LevelFinest, 3);

  _gc_par_phases[FlatProfilerRoots] = new WorkerDataArray<double>(max_gc_threads, "FlatProfiler Roots (ms)", true, G1Log::LevelFinest, 3);

  _gc_par_phases[ManagementRoots] = new WorkerDataArray<double>(max_gc_threads, "Management Roots (ms)", true, G1Log::LevelFinest, 3);

  _gc_par_phases[SystemDictionaryRoots] = new WorkerDataArray<double>(max_gc_threads, "SystemDictionary Roots (ms)", true, G1Log::LevelFinest, 3);

  _gc_par_phases[CLDGRoots] = new WorkerDataArray<double>(max_gc_threads, "CLDG Roots (ms)", true, G1Log::LevelFinest, 3);

  _gc_par_phases[JVMTIRoots] = new WorkerDataArray<double>(max_gc_threads, "JVMTI Roots (ms)", true, G1Log::LevelFinest, 3);

  _gc_par_phases[CodeCacheRoots] = new WorkerDataArray<double>(max_gc_threads, "CodeCache Roots (ms)", true, G1Log::LevelFinest, 3);

  _gc_par_phases[CMRefRoots] = new WorkerDataArray<double>(max_gc_threads, "CM RefProcessor Roots (ms)", true, G1Log::LevelFinest, 3);

  _gc_par_phases[WaitForStrongCLD] = new WorkerDataArray<double>(max_gc_threads, "Wait For Strong CLD (ms)", true, G1Log::LevelFinest, 3);

  _gc_par_phases[WeakCLDRoots] = new WorkerDataArray<double>(max_gc_threads, "Weak CLD Roots (ms)", true, G1Log::LevelFinest, 3);

  _gc_par_phases[SATBFiltering] = new WorkerDataArray<double>(max_gc_threads, "SATB Filtering (ms)", true, G1Log::LevelFinest, 3);




   // 其他功能的时间，如更新、扫描RSet，对象复制，重建Rset、大对象处理等

  _gc_par_phases[UpdateRS] = new WorkerDataArray<double>(max_gc_threads, "Update RS (ms)", true, G1Log::LevelFiner, 2);

  _gc_par_phases[ScanRS] = new WorkerDataArray<double>(max_gc_threads, "Scan RS (ms)", true, G1Log::LevelFiner, 2);

  _gc_par_phases[CodeRoots] = new WorkerDataArray<double>(max_gc_threads, "Code Root Scanning (ms)", true, G1Log::LevelFiner, 2);

  // ...省去一些其他代码

}

上面显示的是需要扫描的根列表。而现场显示的Ext Root Scanning的时间久。而其总和即为下面第7行起后面涉及根扫描的总和。所以如果想知道具体Ext Root Scanning哪部花的时间久，需要把下面的详细日志给输出出来。观察后面的参数，发现大部分需要日志级别达到：G1Log::LevelFinest的时候，会输出对应的信息。也就是对于的G1日志级别为finest。

于是这里调整jvm参数，加上下面这个：

-XX:G1LogLevel=finest

再次观察日志：

服务间歇性停顿问题优化｜得物技术

搜索并查找和SystemDictionaryRoots相关的代码：

void SystemDictionary::roots_oops_do(OopClosure* strong, OopClosure* weak) {

  strong->do_oop(&_java_system_loader);

  strong->do_oop(&_system_loader_lock_obj);

  Ticks start = Ticks::now();

  CDS_ONLY(SystemDictionaryShared::roots_oops_do(strong);)




  // 调整字典

  dictionary()->roots_oops_do(strong, weak);




  // 访问额外的方法

  invoke_method_table()->oops_do(strong);

}

由于不确定是哪行代码导致的请求慢，于是修改源代码，通过使用Ticks::now()获取当前时间，并打印出来。发现耗时最久的其实是dictionary()->roots_oops_do(strong, weak) 这行代码，此方法几乎占用整个方法的99%以上的时间。再仔细翻阅源码，发现此方法内部会遍历
SystemDictionary::dictionary()字典下面所有添加过的项，并根据情况进行标记。这里简单介绍下SystemDictionary::dictionary()：

SystemDictionary::dictionary()维护的是一个全局的static字典。这里虚拟机里面的Dictionary其实就等价于java里面的HashMap。

字典维护的key是Symbol *class_name和ClassLoaderData *loader_data
- class_name即是类的标识符，即类的全限定名称(包名+类名)
- loader_data对应的是java里面的ClassLoader对象。

字典维护的value是DictionaryEntry *对象，这个类有三个字段
- 包括KlassHandle obj，即对应java语言中的class对象，也就是类加载器加载之后返回的类
- 一个hash值，值由key决定，也就是由类全限定名+类加载器计算的int类型值
- 类加载器loader_data

4.3 类加载之 SystemDictionary::dictionary()

想要知道的更多，需要翻阅Dictionary类的源码。找到对应
SystemDictionary::dictionary()添加记录的源码如下：

// class_name对应java里面的类全限定名，包名+类名

// loader_data对应java里面的ClassLoader，类加载器

// obj 对应java里面的类对象，即Class对象

void Dictionary::add_klass(Symbol *class_name, ClassLoaderData *loader_data,

                           KlassHandle obj) {

    assert_locked_or_safepoint(SystemDictionary_lock);

    assert(obj() != NULL, "adding NULL obj");

    assert(obj()->name() == class_name, "sanity check on name");

    assert(loader_data != NULL, "Must be non-NULL");




    unsigned int hash = compute_hash(class_name, loader_data);

    int index = hash_to_index(hash);

    DictionaryEntry *entry = new_entry(hash, obj(), loader_data);

    add_entry(index, entry);

}

4.4 基本的加载动作 SystemDictionary::resolve_instance_class_or_null

Klass* SystemDictionary::resolve_instance_class_or_null(Symbol* name,

                                                        Handle class_loader,

                                                        Handle protection_domain,

                                                        TRAPS) {

   ...省去一些代码

  EventClassLoad class_load_start_event;




  class_loader = Handle(THREAD, java_lang_ClassLoader::non_reflection_class_loader(class_loader()));

  ClassLoaderData *loader_data = register_loader(class_loader, CHECK_NULL);




  // 类符号名name+类加载器loader_data当作key

  // 并且访问者是否有访问权限时候

  // 从dictionary获取缓存的Klass

  // 如果没有获取成功，后面会触发类加载操作，并将加载完成的类放到dictionary中

  unsigned int d_hash = dictionary()->compute_hash(name, loader_data);

  int d_index = dictionary()->hash_to_index(d_hash);

  Klass* probe = dictionary()->find(d_index, d_hash, name, loader_data,

                                      protection_domain, THREAD);

  if (probe != NULL) return probe;




  ...省去一些代码

  }

在java里面唯一确认一个类的方式就是类加载器+类全限定名称，并且在类加载里面存在缓存机制，同一个类加载器+类限定名加载的类仅会加载一次，从上面的代码可以看到，这个记录它就记录在
SystemDictionary::dictionary()里面！大致加载流程如下：

服务间歇性停顿问题优化｜得物技术

4.5 拨开迷雾

所以，本文所描述的问题的根本原因找到了：

a. 因为每次new的都是一个不同的CompositeClassLoader，所以每次这个类加载器加载类的时候，都会调用Dictionary::add_klass方法往
SystemDictionary::dictionary()插入一些记录，而SystemDictionary::dictionary() 所引用的字段是一个用static修饰的全局变量。

b.
SystemDictionary::dictionary()对象在YGC的时候并不释放，虽然本场景下其大部分对象都是不可达的，（SystemDictionary::dictionary()中不可达的对象只会在mix-gc或者full-gc的时候才会回收和卸载）。

c. YGC的时候，会遍历
SystemDictionary::dictionary()，并且将符合条件的对象当作root进行根扫描。

d. 由于程序以错误的方式不停的执行类加载操作(无法使用缓存)，导致不停的往
SystemDictionary::dictionary() 插入记录，以至于SystemDictionary::dictionary()一度膨胀到有上千万条记录(50万+的CompositeClassLoader，每个CompositeClassLoader会加载40次类，共2000万+条记录)。虽然是内存遍历，但是这么庞大的数据量，再强劲的CPU也需要花很多时间。可想而知：YGC漫长的原因由此而来！

5.知识小结

5.1 类加载

类和接口的名称，都是通过全限定形式(fully qualified form)表示。如java.lang.Thread表示为java/lang/Thread
类加载器
- 如果一个类加载器L直接创建了一个类C，那么称之为L是C的定义加载器(defininng loader)
- 如果一个类加载器L负责加载某个类C，但是实际将加载动作委托给了其他类加载器，那么L称为C的初始类加载器(initiating loader)
- 如果一个类L加载了一个类或者接口C，那么会往SystemDictionary::dictionary()插入两条条记录，分别是定义类加载器+C、初始类加载器+C。同时将这个类也起到了一个缓存作用，类加载器加载相同的类的时候，避免重复加载
- 根据的实际业务场景，避免重复创建相同功能的类加载器

5.2 YGC&G1

在JDK8中，G1可以说是最热门，同时也是最成熟的垃圾收集器
G1将内存分为很多个区，为了满足期望的停顿时间，并不会回收全部的区
G1的YGC会一次性回收所有的新生代对象，并且伴有STW
G1在YGC中的根扫描包含Java根和Jvm根。Java根包括线程栈和类加载器，Jvm根通常是一些全局的变量
可以开启如下参数，以便获取更详细一点的GC日志信息：

-XX:+UnlockExperimentalVMOptions

-XX:G1LogLevel=finest

5.3 XStream

翻阅XStream的源码，可以看到如下注释：

服务间歇性停顿问题优化｜得物技术

官方已经说了，XStream类本身就是线程安全的，建议使用单例模式使用！

所以说：使用第三类和工具的时候，有必要花些时间去了解下这个类，避免踩坑！