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上。

关于Java启动性能的一个解决方法

之前的一篇文章里说到我们最近碰到的一个困扰,就是单机优化后支撑的qps(每秒请求量)确实变高了,但在高峰重启的时候有些时候会一直卡在解释执行模式,导致rt不理想,经@rednaxelafx 大神指点,可以加一个参数来基本解决。

@rednaxelafx 告诉我可以尝试加一个-XX:CICompilerCount参数来试试,这个值默认是2,也就是说2个c2的编译线程来进行编译,我改为了cpu core数的一半,重新启动了下效果明显比以前好了很多,load还是会冲高,不过下降的很快,因此说明这个参数是work的。

既然启动的时候访问量比较大,如果一直耗在解释执行时状况其实也不会多好,确实不如多拿几个线程来做编译,加快达到高峰性能的速度,而到达了高峰后,多这几个编译线程对整体并不会有什么影响。

因此看起来貌似在目前的情况下,Java启动的时候性能差在cpu够的情况下用这个办法还是能得到比较明显的缓解的,挺好的。

————————————————

之前的文章里应该是有讲过有些系统比较多的cpu消耗在了JVM_internString上,这个只有java.lang.String.intern才会调用到,可是我之前用btrace一直都没跟到谁调了这个地方,看来native method确实是不太好跟到,今天请JVM Team的人帮忙改了下JVM,允许动态打开一个参数来从JVM层面输出调JVM_internString的堆栈信息,有了这个后很快就看到了具体调用String.intern的地方,目前看起来是做序列化/反序列化的地方会调的比较多,这个对于有远程交互的应用来说会比较正常,例如java.io.ObjectStreamField的构造器代码:
public ObjectStreamField(String name, Class type, boolean unshared) {
if (name == null) {
throw new NullPointerException();
}
this.name = name;
this.type = type;
this.unshared = unshared;
signature = ObjectStreamClass.getClassSignature(type).intern();
field = null;
}

JVM会将String.intern的值放在StringTable(一个类似HashTable的结构)里,默认大小是1009,在6u34前或7前的版本,是不允许设置的,这就会导致如果很多值的话,会导致冲突严重,而使得链表很长,那么在调用String.intern的时候由于遍历链表,会导致耗CPU会比较多。

————————————————

最近有个应用还碰到比较明显的CMS GC时ygc时间有点偏慢的现象,后来dump内存分析的时候看到有个较大的数据结构是一直存活的,问了下开发,这个数据结构里的对象是会经常变的,对于这种情况,CMS GC的ygc速度是会受到一些影响的(话说不仅仅是cms gc,所有GC都会),原因是ygc的时候需要扫描卡表,这个卡表主要是标识新生代中哪些对象是被旧生代引用了的,这种需要尽可能避免,但确实不好做到。

=============================
题图来源于:http://cn.wsj.com/pictures/photo/Another_Lamborghini_Supercar/06.jpg
欢迎关注微信公众号:hellojavacases

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

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