深入 JVM 彻底剖析 ygc 越来越慢的原因(下)

阅读数:3496 2016 年 5 月 11 日

话题:JVM语言 & 开发架构

阿里 JVM 团队的同学帮助从 JVM 层面继续深入的剖析了下前面那个 ygc 越来越慢的 case,分析文章相当的赞,思路清晰,工具熟练,JVM 代码熟练,请看这位同学(阿里 JVM 团队:寒泉子)写的文章,我转载到这。

Demo 分析

虽然这个 demo 代码逻辑很简单,但是其实这是一个特殊的 demo,并不简单,如果我们将 XStream 对象换成 Object 对象,会发现不存在这个问题,既然如此那有必要进去看看这个 XStream 的构造函数(请大家直接翻 XStream 的代码,这里就不贴了)。

这个构造函数还是很复杂的,里面会创建很多的对象,上面还有一些方法实现我就不贴了,总之都是在不断构建各种大大小小的对象,一个 XStream 对象构建出来的时候大概好像有 12M 的样子。

那到底是哪些对象会导致 ygc 不断增长呢,于是可能想到逐步替换上面这些逻辑,比如将最后一个构造函数里的那些逻辑都禁掉,然后我们再跑测试看看还会不会让 ygc 不断恶化,最终我们会发现,如果我们直接使用如下构造函数构造对象时,如果传入的 classloader 是 AppClassLoader,那会发现这个问题不再出现了,代码如下:

复制代码
public static void main(String[] args) throws Exception {
    int i=0;
    while (true) {
        XStream xs = new XStream(null,null, new ClassLoaderReference(XStreamTest.class.getClassLoader()),null, new DefaultConverterLookup());
        xs.toString();
        xs=null;
    }
}

是不是觉得很神奇,由此可见,这个 classloader 至关重要。

不得不说的类加载器

这里着重要说的两个概念是初始类加载器和定义类加载器。举个栗子说吧,AClassLoader->BClassLoader->CClassLoader,表示 AClassLoader 在加载类的时候会委托 BClassLoader 类加载器来加载,BClassLoader 加载类的时候会委托 CClassLoader 来加载,假如我们使用 AClassLoader 来加载 X 这个类,而 X 这个类最终是被 CClassLoader 来加载的,那么我们称 CClassLoader 为 X 类的定义类加载器,而 AClassLoader 和 BClassLoader 分别为 X 类的初始类加载器,JVM 在加载某个类的时候对这三种类加载器都会记录,记录的数据结构是一个叫做 SystemDictionary 的 hashtable,其 key 是根据 ClassLoader 对象和类名算出来的 hash 值,而 value 是真正的由定义类加载器加载的 Klass 对象,因为初始类加载器和定义类加载器是不同的 classloader,因此算出来的 hash 值也是不同的,因此在 SystemDictionary 里会有多项值的 value 都是指向同一个 Klass 对象。

那么 JVM 为什么要分这两种类加载器呢,其实主要是为了快速找到已经加载的类,比如我们已经通过 AClassLoader 来触发了对 X 类的加载,当我们再次使用 AClassLoader 这个类加载器来加载 X 这个类的时候就不需要再委托给 BClassLoader 去找了,因为加载过的类在 JVM 里有这个类加载器的直接加载的记录,只需要直接返回对应的 Klass 对象即可。

Demo 中的类加载器是否会加载类

我们的 demo 里发现构建了一个 CompositeClassLoader 的类加载器,那到底有没有用这个类加载器加载类呢,我们可以设置一个断点在 CompositeClassLoader 的 loadClass 方法上,可以看到会进入断点。

可见确实有类加载的动作,根据类加载委托机制,在这个 Demo 中我们能肯定类是交给 AppClassLoader 来加载的,这样一来 CompositeClassLoader 就变成了初始类加载器,而 AppClassLoader 会是定义类加载器,都会在 SystemDictionary 里存在,因此当我们不断 new XStream 的时候会不断 new CompositeClassLoader 对象,加载类的时候会不断往 SystemDictionary 里插入记录,从而使 SystemDictionary 越来越膨胀,那自然而然会想到如果 GC 过程不断去扫描这个 SystemDictionary 的话,那随着 SystemDictionary 不断膨胀,那么 GC 的效率也就越低,抱着验证下猜想的方式我们可以使用 perf 工具来看看,如果发现 cpu 占比排前的函数如果都是操作 SystemDictionary 的,那就基本验证了我们的说法,下面是 perf 工具的截图,基本证实了这一点。

SystemDictionary 为什么会影响 GC 过程

想象一下这么个情况,我们加载了一个类,然后构建了一个对象 (这个对象在 eden 里构建) 当一个属性设置到这个类里,如果 gc 发生的时候,这个对象是不是要被找出来标活才行,那么自然而然我们加载的类肯定是我们一项重要的 gc root,这样 SystemDictionary 就成为了 gc 过程中的被扫描对象了,事实也是如此,可以看 vm 的具体代码(代码在:SharedHeap::process_strong_roots,感兴趣的同学可以直接翻这部分代码)。

看上面的SH_PS_SystemDictionary_oops_do task就知道了,这个就是对 SystemDictionary 进行扫描。

但是这里要说的是虽然有对 SystemDictionary 进行扫描,但是 ygc 的过程并不会对 SystemDictionary 进行处理,如果要对它进行处理需要开启类卸载的 vm 参数,CMS 算法下,CMS GC 和 Full GC 在开启 CMSClassUnloadingEnabled 的情况下是可能对类做卸载动作的,此时会对 SystemDictionary 进行清理,所以当我们在跑上面 demo 的时候,通过jmap -dump:live,format=b,file=heap.bin命令执行完之后,ygc 的时间瞬间降下来了,不过又会慢慢回去,这是因为 jmap 的这个命令会做一次 gc,这个 gc 过程会对 SystemDictionary 进行清理。

修改 VM 代码验证

很遗憾 hotspot 目前没有对 ygc 的每个 task 做一个时间的统计,因此无法直接知道是不是SH_PS_SystemDictionary_oops_do这个 task 导致了 ygc 的时间变长,为了证明这个结论,我特地修改了一下代码,在上面的代码上加了一行:GCTraceTime t(“SystemDictionary_OOPS_DO”,PrintGCDetails,true,NULL);然后重新编译,跑我们的 demo,测试结果如下:

2016-03-14T23:57:24.293+0800: [GC2016-03-14T23:57:24.294+0800: [ParNew2016-03-14T23:57:24.296+0800: [SystemDictionary_OOPS_DO, 0.0578430 secs]  
: 81920K->3184K(92160K), 0.0889740 secs] 81920K->3184K(514048K), 0.0900970 secs] [Times: user=0.27 sys=0.00, real=0.09 secs]  
2016-03-14T23:57:28.467+0800: [GC2016-03-14T23:57:28.468+0800: [ParNew2016-03-14T23:57:28.468+0800: [SystemDictionary_OOPS_DO, 0.0779210 secs]  
: 85104K->5175K(92160K), 0.1071520 secs] 85104K->5175K(514048K), 0.1080490 secs] [Times: user=0.65 sys=0.00, real=0.11 secs]  
2016-03-14T23:57:32.984+0800: [GC2016-03-14T23:57:32.984+0800: [ParNew2016-03-14T23:57:32.984+0800: [SystemDictionary_OOPS_DO, 0.1075680 secs]  
: 87095K->8188K(92160K), 0.1434270 secs] 87095K->8188K(514048K), 0.1439870 secs] [Times: user=0.90 sys=0.01, real=0.14 secs]  
2016-03-14T23:57:37.900+0800: [GC2016-03-14T23:57:37.900+0800: [ParNew2016-03-14T23:57:37.901+0800: [SystemDictionary_OOPS_DO, 0.1745390 secs]  
: 90108K->7093K(92160K), 0.2876260 secs] 90108K->9992K(514048K), 0.2884150 secs] [Times: user=1.44 sys=0.02, real=0.29 secs]

我们会发现 YGC 的时间变长的时候,SystemDictionary_OOPS_DO的时间也会相应变长多少,因此验证了我们的说法。

有同学提到如果 Demo 代码改成不 new XStream,而是直接 new CompositeClassLoader 或 CustomClassLoader 则不会出问题,按照上面的分析也很容易解释,就是因为如果直接 new CustomClassLoader 的话,并没触发 loadClass 这动作,而 new XStream 的话在构造器里就在 loadClass。

有同学提到在 JDK 8 中跑这个 case 不会出现问题,原因是:jdk8 在对 SystemDictionary 扫描时做了优化,增加了一层 cache,大大减少了需要扫描的入口数。


感谢魏星对本文的审校。

给 InfoQ 中文站投稿或者参与内容翻译工作,请邮件至editors@cn.infoq.com。也欢迎大家通过新浪微博(@InfoQ@丁晓昀),微信(微信号:InfoQChina)关注我们。