服务间歇性停顿问题优化｜得物技术
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())) {@Overrideprotected 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进行根扫描。
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日志信息：
5.3 XStream
翻阅XStream的源码，可以看到如下注释：
官方已经说了，XStream类本身就是线程安全的，建议使用单例模式使用！
所以说：使用第三类和工具的时候，有必要花些时间去了解下这个类，避免踩坑！
*文/钟卫安
要是觉得文章对你有帮助的话，欢迎评论转发点赞～
709 得物技术沙龙《数据库架构&数据库稳定性治理》PPT已上传，领取方式：得物技术公众号后台回复「PPT」即可领取。 709 得物技术沙龙《云原生架构实践》视频回放已经上传，取方式：得物技术公众号后台回复「回放」即可领取。