记一次频繁YGC导致系统越来越慢问题排查

事件起因是一个mq消费服务出现了消息积压，查看系统请求日志，发现大量请求耗时两三秒以上，甚至10秒以上的消费时间。服务重启后就恢复正常，而且是有规律性的大概2天出现一次。根据以上情况初步判断是和JVM的垃圾回收有关。打印的GC日志如下：

从日志上可以看出一次YGC的时间大概是2.7秒左右，而且是每10秒出现一次，这个STW的时间和频率已经很不正常了，而且问题出在 Ext Root Scanning阶段，也就是堆外 gc roots扫描时间过长。这个Ext Root Scanning一时半会无法找出是什么原因，可能和同步锁有关，也可能和加载的类信息等有关，接下来可以打印出线程栈信息来分析。

    阿里有一款在线诊断利器arthas很好用，thread -n 3 -i 1000 打印出1000ms内最忙的3个线程栈，如下图：

前三个线程栈全指向同一个方法，那就是XStream的XML对象转换方法，查看代码发现这个XStream对象每次都会new一个，问题可能就是出在这里了。进XStream的构造方法看看，发现XStream初始化的对象还真多，里面出现了一个类加载器CompositeClassLoader，而且是每次new出来的

通过截图可以看出，每次操作xml都会通过Class.forName反射操作，java反射本身是有一定的性能开销的，每一次反射操作都会有安全性验证开销，而且也损失一些jvm的优化操作。不过，我认为这只是造成线程性能开销大的原因，gc的时间是耗在 gc roots的扫描上，个人认为这可能是和每一次都new一个CompositeClassLoader加载器有关，这一部分估计是垃圾无法回收的吧，随着时间的推移，每一次扫描耗时过长，从而造成STW耗时长。

    最终解决办法就是XStream对象改成单例的

标签：一次,YGC,导致系统,XStream,排查,线程,new,gc,日志
来源： https://blog.csdn.net/xiaofo258/article/details/121492230