stringLiterals2

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

《YGC越来越慢,为什么》有2个想法

发表评论

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


*