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

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