YGC越来越慢，为什么 – hellojavacases微信公众号网站
近来被这个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还是别用好了，除非真的是重复量非常大的相同字符串处理。
Read full article from YGC越来越慢，为什么 – hellojavacases微信公众号网站
No comments:
Post a Comment