一次GC Tuning小记

24 Sep 2016

互联网时代,版本开发的节奏是非常快的,一般一周或两周都会有一个版本,就在最近的一次版本发布后,日常监控的同学发现版本上线后FullGC的频率突然由之前的几周一次变成了一天几次,虽然没有引起什么明显的性能问题,但这个发现还是引起了我们的注意,于是就有了这篇小记。

背景

出现问题的应用是一个高并发的服务接口,业务逻辑比较简单,对内存的消耗很小,JVM开的内存大小为2G,新生代,老生代各1G,老生代GC算法采用CMS,新生代采用ParallelGC。

问题现象

前面也提到了,最近一次版本发布后,老生代增长突然加快很多,导致FullGC的频率变快。而每次FullGC的停顿时间相对较长,可能引起GC期间的服务接口响应时间延迟而导致前端调用超时。

问题分析

看到这个问题后,心里先是一凉,很明显是代码的改动引起的,所以一开始就是怀疑代码是否有bug,引起某些对象不能被YGC回收,不断的放到老生代。接着把上线前后两个版本分别在测试环境对比跑上一把,结果在测试环境很容易就可以重现出来。于是信心油然而生,可以重新的问题,一定有办法解决,啪啦啪啦几下,heap dump搞到手,就开始吭哧吭哧的分析起来。

拿了前后两个版本的heap dump分析,看到的对象也都差不多,并不能找到存留在老生代里的对象到底是什么,因为若是仅查看live的对象,老生代里迅速增长的对象也被GC掉了,若是不用live,看整个heap对象,又分不清哪些是在老生代,而哪些是在新生代。

重新思考

于是停下来,再思考下,为什么有对象会被放进老生代,真是因为YGC干不掉而被挪进老生代的吗?能否找到证据,一步步再往下分析?加上gc的几个启动参数: -Xloggc, -XX:+PrintGCDetails, -XX:+PrintTenuringDistribution, 将GC的详细日志打印出来,问题也跟着慢慢浮现出来。

新版本的gc日志:

2016-09-13T20:17:03.185+0800: 52.439: [GC2016-09-13T20:17:03.185+0800: 52.439: [ParNew Desired survivor size 53673984 bytes, new threshold 1 (max 6)
- age   1:   59223016 byte,   59223016 total
: 921484K->84871K(943744K), 0.0278960 secs] 1043598K->206985K(1992320K), 0.0281660 secs] [Times: user=0.46 sys=0.01, real=0.03 secs] 

旧版本的gc日志:

2016-09-13T20:19:18.782+0800: 28.403: [GC2016-09-13T20:19:18.782+0800: 28.403: [ParNew
Desired survivor size 53673984 bytes, new threshold 1 (max 6)
- age   1:   57712976 bytes,   57712976 total
- age   2:     134352 bytes,   57847328 total
- age   3:     128496 bytes,   57975824 total
- age   4:     408520 bytes,   58384344 total
- age   5:    1256024 bytes,   59640368 total
: 928083K->88968K(943744K), 0.0401070 secs] 1032852K->208118K(1992320K), 0.0404620 secs] [Times: user=0.44 sys=0.01, real=0.04 secs] 

我们配置的MaxTenuringThreshold是6,但为什么新版本YGC之后,只有age为1的对象,没有age是2,3,4,5,6的呢?再仔细看这段日志:ParNew Desired survivor size 53673984 bytes,这个的意思是survivor区期望最多放下的对象大小为53673984 bytes,若是超过了这个大小,不好意思,survivor收容不了,只能放进老生代。再看我们age为1的对象有多大,59223016 byte,刚好超过了这个大小,被直接放进了老生代,这也就是为什么老生代增长变快的原因了。

如何解决

第一个问题:Desired survivor size 53673984 bytes,为什么是53673984 bytes?这就要看看我们的内存大小分配了,NewRatio=1,SurvivorRatio用的默认值8,可以算出Survivor区大小是107347968,而Desired survivor size则是Survivor区大小的50%(TargetSurvivorRatio的默认值)。

第二个问题:Desired survivor size 这个值是做什么用的?这个值是设定Eden区被YGC完后的对象允许被搬到survivor区的最大值,可调整,调大一点,就可以让更多的新生代对象在survivor游荡几圈,如果这些对象并没有被很多地方引用到,可以直接在新生代消亡,不用再到老生代,这样也可以减轻老生代的压力。反过来思考我们这个应用,绝大部分对象都是短生命周期的,只有一些比如本地缓存的对象(都是些配置信息,对象增长非常缓慢),是会留在老生代,所以,调大TargetSurvivorRatio是一种解决方案。

当然,还有其他的解决办法,比如加大survivor区的大小,但这样一来,Eden区大小缩减,YGC会更频繁;又或者加大内存空间,但担心GC的停顿时间加长。

所以,最终的解决办法还是保持各个区的大小不变,只是将TargetSurvivorRatio调整到75%,再观察上一段时间验证,老生代的快速增长的问题最终得以解决。

总结


image