上篇文章中ygc越来越慢的case的原因解读

上篇文章中附加了一个最近碰到的奇怪的case,有位同学看到这个后周末时间折腾了下,把原因给分析出来了,分析过程很赞,非常感谢这位同学(阿里的一位同事,花名叫彦贝),在征求他的同意后,我把他写的整个问题的分析文章转载到这里。

    上分析工具VisualVM

在解决很多问题的时候,工具起的作用往往是巨大,很多时候通过工具分析,很快便能找到原因,但是这次并没有,下图是VisualVM观察到Heap上的GC图表。
visualvm

从图标中可以看出,Perm区空间基本水平,但是Old区空间成增长态势与YGCT时间增长的倍率基本一直。熟悉YGC的朋友都知道YGC主要分为标记和收回两个阶段,YGCT也是基于这2个阶段统计的。由于每次回收的空间大小差不多,所以怀疑是标记阶段使用的时间比较长,下面回顾一下JVM的垃圾标记方式。

    JVM垃圾回收的标记方法-枚举根节点

在Java语言里面,可作为GC Roots的节点主要在全局性的引用(例如常量或类静态属性)与执行上下文(例如栈帧中的本地变量表)中。如果要使用可达性分析来判断内存是否可回收的,那分析工作必须在一个能保障一致性的快照中进行——这里“一致性”的意思是整个分析期间整个执行系统看起来就像被冻结在某个时间点上,不可以出现分析过程中,对象引用关系还在不断变化的情况,这点不满足的话分析结果准确性就无法保证。这点也是导致GC进行时必须“Stop The World”的其中一个重要原因,即使是号称(几乎)不会发生停顿的CMS收集器中,枚举根节点时也是必须要停顿的。

由于目前的主流JVM使用的都是准确式GC,所以当执行系统停顿下来之后,并不需要一个不漏地检查完所有执行上下文和全局的引用位置,虚拟机应当是有办法直接得到哪些地方存放着对象引用。在HotSpot的实现中,是使用一组成为OopMap的数据结构来达到这个目的,在类加载完成的时候,HotSpot就把对象内什么偏移量上是什么类型的数据计算出来,在JIT编译过程中,也会在特定的位置记录下栈里和寄存器里哪些位置是引用。这样GC在扫描时就就可以直接得知这些信息了。
上面这段引用自《深入理解Java虚拟机》,用个图简单表示一下,当然图也是源于书中:
gcrootset

基于对GC Roots的怀疑,猜测Old区中存在越来越多的gc root节点,那什么样的对象是root节点呢?不懂的我赶紧google了一下。
gcroots

(不要看我红色圈出来了,第一次看到这几个嫌疑犯时我也拿不准是哪个)

为了进一步验证是Old区的GC Roots造成YGCT 增加的,我们来做一次full gc,干掉Old区。代码如下:

public class SlowYGC {
public static void main(String[] args) throws Exception {
int i= 0;
while (true) {
XStream xs = new XStream();
xs.toString();
xs = null;
if(i++ % 10000 == 0)
{
System.gc();
}
}
}
}

可以看出Full GC后 YGCT锐减到初始状态。那是Full GC到底回收了哪些对象?进入到下一步,增加VM参数。

增加VM参数
为了看到Full GC前后对象的回收情况,我们增加下面2个VM参数
-XX:+PrintClassHistogramBeforeFullGC -XX:+PrintClassHistogramAfterFullGC。
重新运行上面的代码,可以观察到下面的日志:
vmlog

上图左边是FGC前的对象情况,右边是FGC后的情况,结合我之前给出的GC Root候选人中的Monitor锁,相信你很快就找到20026个[Ljava.util.concurrent.ConcurrentHashMap$Segment对象几乎被全部回收了,ConcurrentHashMap中正是通过Segment来实现分段锁的。那什么逻辑会导致出现大量的Segment锁对象。继续看Full GC日志com.thoughtworks.xstream.core.util.CompositeClassLoader这个对象也差不多在FGC的时候全军覆没,所以怀疑是ClassLoader引起的锁竞争,下面在ClassLoader的源码中继续查找。

ClassLoader中的ConcurrentHashMap
classloader

这里有个拿锁的动作,跟进去看看呗。
parallelLockMap

为了验证走到这块逻辑下了一个断点。剩下的就是putIfAbsent方法(这里就不详细分析实现了)有兴趣的同学可以看看源码中CAS和tryLock的使用。
至此基本分析和定位出了YGCT原因,在去看看Xstream的构造函数。
xstream
可以看出每次new XstreamI()的同时会new一个新的ClassLoader,基本上证明了上述怀疑和猜测。

推导一下按照上述分析,应该是所有自定义的ClassLoader都会YGCT变长的时间问题,于是手写一个ClassLoader验证一下。Java代码如下:

public class TestClassLoader4YGCT {
public static void main(String[] args) throws Exception{
while(true)
{
Object obj = newObject();
obj.toString();
obj = null;
}
}

private static Object newObject() throws Exception
{
ClassLoader classLoader = new ClassLoader() {
@Override
public Class loadClass(String s) throws ClassNotFoundException {
try{
String fileName = s.substring(s.lastIndexOf(“.”) + 1)+ “.class”;
InputStream inputStream = getClass().getResourceAsStream(fileName);
if(inputStream == null){
return super.loadClass(s);
}
byte[] b = new byte[inputStream.available()];
inputStream.read(b);
return defineClass(s,b,0,b.length);
}catch (Exception e)
{
System.out.println(e);
return null;
}
}
};
Class obj = classLoader.loadClass(“jvmstudy.classload.TestClassLoader4YGCT”);
return obj.newInstance();
}
}
VM 参数-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xms512m -Xmx512m -Xmn100m -XX:+UseConcMarkSweepGC

GC日志
lastgclog

结论
当大量new自定义的ClassLoader来加载时,会产生大量ClassLoader对象以及parallelLockMap(ConcurrentHashMap)对象,导致产生大量的Segment分段锁对象,大大增加了GC Roots的数量,导致YGC中的标记时间变长。如果能直接看到YGCT的详细使用情况,这个结论会显得更加严谨。这只是我自己的一个推导,并不一定是正确答案。

=============================
欢迎关注微信公众号:hellojavacases

关于此微信号:
分享Java问题排查的Case、Java业界的动态和新技术、Java的一些小知识点Test,以及和大家一起讨论一些Java问题或场景,这里只有Java细节的分享,没有大道理、大架构和大框架。

公众号上发布的消息都存放在http://hellojava.info上。

《上篇文章中ygc越来越慢的case的原因解读》有2个想法

  1. 测试了一下,没有出现大量的20026个[Ljava.util.concurrent.ConcurrentHashMap$Segment,只有几十个。
    但是确实存在大量的com.thoughtworks.xstream.core.util.CompositeClassLoader

发表评论

电子邮件地址不会被公开。 必填项已用*标注


*