YGC越来越慢,为什么

近来被这个case折腾的很,现象是有个应用在压测时qps表现不太稳定,好和不好的时候差别还挺大的,对比好和不好的时候,看到的现象就是好的时候ygc时间会比较短,而不好的时候ygc时间比较长,然后看正常运行的时候,也看到一个现象就是ygc时间会越来越长,直到cms gc触发后才能降回到一个比较小的值,于是开始查为什么ygc会越来越慢。

YGC越来越慢,还真没什么太多信息可入手的,于是求助JVM团队的寒泉子(微信公众号:lovestblog,强烈推荐)帮忙输出一些ygc分阶段的耗时信息,以便来推测到底是哪部分造成的ygc慢,例如我有点怀疑的是oldgen碎片的问题造成的,但通常碎片问题呢cms gc后也很难有太大程度的缓解,所以和这个现象不太一样。

拿到有更多trace信息的JDK版本后,更新上线,根据ygc不断变慢的trace信息对比发现问题出在了StringTable部分,这是ygc速度正常的情况下StringTable部分的速度:
[StringTable::possibly_parallel_oops_do_21030, 0.0010919 secs]
而ygc越来越慢后,StringTable部分:
[StringTable::possibly_parallel_oops_do_11152162, 0.1101763 secs]
从输出信息来看,可以看到在ygc速度还正常的时候,StringTable去扫的一个桶里的item数才21030个,而到了ygc速度很慢的时候,item数增长到了11152162个,这样的数量增长StringTable处理的速度变慢也是正常的。

那就要查查为什么StringTable增长那么快了,StringTable增长基本都是String.intern搞的(关于StringTable和String.intern推荐看看这篇文章:http://java-performance.info/string-intern-in-java-6-7-8/),不过这个方法在native,btrace跟不了,所以寒泉子继续改了个JDK版本,采样的输出String.intern的栈信息,这个版本放上去跑后,很快看到这样的堆栈信息:
at java.lang.String.intern(Native Method)
at com.fasterxml.jackson.core.util.InternCache.intern(InternCache.java:45)
跟着这个栈信息翻对应的代码(话说不知道大家都用什么去查代码呢,我一般都用www.grepcode.com,觉得挺好用的),很容易明白问题所在,例如InternCache.intern部分的代码如下:
if (result == null) {
result = input.intern();
put(result, result);
}

jackson之所以用intern去处理,本来是想节省点cache的内存,没想到业务场景是每次都不一样的字符串,这样直接就导致了String.intern后StringTable的大小暴涨,所以在这种场景中,这样做反而得不偿失,还好jackson代码支持通过接口来把调用intern的部分关掉。

话说用String.intern不当造成的StringTable大,从而导致ygc速度慢这问题我好像碰过好几次了,而且到现在我都觉得StringTable这东西的设计不咋样,建议大家能不用String.intern还是别用好了,除非真的是重复量非常大的相同字符串处理。

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

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

JDK7里的String.intern的变化

有一段这样的代码:
[code]
for (int i = 0; i < 10000000; i++) { ("bluedavy" + i).intern(); if(i % 100 == 0) Thread.sleep(1); } [/code] 大家可以分别用这段代码在JDK 6里和JDK 7里跑跑看看,会有什么不同。 上面的代码在JDK 7里执行时比JDK 6将会更多的触发Young GC和Full GC,原因请见这段描述: In JDK 7, interned strings are no longer allocated in the permanent generation of the Java heap, but are instead allocated in the main part of the Java heap (known as the young and old generations), along with the other objects created by the application. This change will result in more data residing in the main Java heap, and less data in the permanent generation, and thus may require heap sizes to be adjusted. Most applications will see only relatively small differences in heap usage due to this change, but larger applications that load many classes or make heavy use of the String.intern() method will see more significant differences. 简单来说就是在JDK 7里String.intern生成的String不再是在perm gen分配,而是在Java Heap中分配,因此自然上面的这段代码在JDK 7里会产生更为严重的Young GC和Full GC,就像上面这段描述里说的一样,这个变化对于装载了很多类的应用估计还是会有些明显的影响,对反射使用多的其实也会有些影响。 关于这个变化,在Stack Overflow上还有个有趣的case: [code] class Test { public static void main(String... args) { String s1="Good"; s1=s1+"morning"; System.out.println(s1.intern()); String s2="Goodmorning"; System.out.println(s1==s2); } } [/code] 上面这段代码在目前的JDK 6里和JDK 7里竟然会不同,JDK6里会输出false,而JDK 7会输出true,原因是JDK 6中执行String.intern时需要将此字符串的实例cp到perm并生成一个新的String对象,因此上面的s1和s2的对象地址是不同的,而在JDK 7中,执行String.intern时,则只是在String Pool中记录此字符内容对应的字符串实例。 尽管在比较字符串时,一般都不会用 == 去比较,但还是要知道String.intern的这个变化。 String.intern放进的String Pool是一个固定大小的Hashtable,默认值是1009,如果放进String Pool的String非常多,就会造成Hash冲突严重,从而导致链表会很长,而链表长了后直接会造成的影响就是当调用String.intern时性能会大幅下降(因为要一个一个找)。 之前碰到过一个频繁抛异常造成cpu us很高的case:http://bluedavy.me/?p=409
现在仔细想想,看来当时这个case并不是因为频繁抛异常造成的,而是因为这个case中抛的是NoSuchMethodException,而抛这个异常的原因是因为调用了Class.getMethod找方法没找到,在class.getMethod这方法的实现里会调用name.intern,而很不幸的是这个case里传入的name会根据请求而变,因此导致了String Pool中放入了很多的String,hash冲突严重,链表变长,从而才导致了造成了String.intern过程变得比较耗CPU。

JDK为了解决这个问题,在6u32以及JDK 7的版本里支持了StringTable大小的配置功能,可在启动参数上增加-XX:StringTableSize来设置,具体的信息见:http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6962930
不过目前JDK未提供方法来查看StringTable中各桶的链表长度,如果提供这个的话就更好了。

———-互动时间———–
问:java.lang.Object是接口的超类吗?
答:话说这个其实我也答不上,咨询了下@rednaxelafx,回答是java.lang.Object不是接口的超类,原因是:接口无法直接实例化,能实例化的都是非抽象类,而所有Java类的顶层类型就是java.lang.Object,所以所有Java对象都必然有java.lang.Object的方法
所以就有了这样的特殊规定,说即便是对接口调用Object上的方法也可以,在JVM内部还有专门的特殊处理来支持这个,语言和JVM内都有特殊规定。

问:java 占用的内存,在top命令就是RES么?和另外两个值VIRT 与SWAP又是怎么个关系呢?
答:top命令看到的RES是其占用的实际内存空间大小,VIRT是占用的地址空间大小,SWAP是用到了SWAP区的大小。

=============================
欢迎关注微信公众号:hellojavacases
关于此微信号:
用于分享Java的一些小知识点,Java问题排查的Cases,Java业界的动态,以及和大家一起互动讨论一些Java的场景和问题。

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