JVM GC一次调优实战

摘要

如果你的服务日志卡住了，请求不处理了，可能是JVM在垃圾回收，前后耗时一周左右，对线上服务的jvm进行了一次优化

CMS的Full GC采用压缩式垃圾收集，在堆比较大的时候，如果full gc频繁，会导致停顿，并且调用方阻塞、超时、甚至雪崩的情况出现，所以降低full gc的发生频率和需要时间，非常有必要。

目标

• 减少full gc频率
• 减少ygc和full gc时间

优化

配置变化

优化前

<jvm-arg>-Xmx13312m</jvm-arg><jvm-arg>-Xms9216m</jvm-arg><jvm-arg>-Xmn1024m</jvm-arg><jvm-arg>-XX:PermSize=512M</jvm-arg><!-- 使用cms回收策略 --><jvm-arg>-XX:+UseParNewGC</jvm-arg><jvm-arg>-XX:+UseConcMarkSweepGC</jvm-arg><!-- 打印gc日志 --><jvm-arg>-XX:+PrintGCDetails</jvm-arg><jvm-arg>-XX:+PrintGCDateStamps</jvm-arg><jvm-arg>-XX:+PrintHeapAtGC</jvm-arg><jvm-arg>-Xloggc:log/gc.log</jvm-arg>

优化后：

<jvm-arg>-Xmx13312m</jvm-arg><jvm-arg>-Xms13312m</jvm-arg><jvm-arg>-Xmn5120m</jvm-arg><jvm-arg>-XX:PermSize=512M</jvm-arg><jvm-arg>-XX:+UseParNewGC</jvm-arg><jvm-arg>-XX:+UseConcMarkSweepGC</jvm-arg><!-- 每次full gc之后，进行压缩 --><jvm-arg>-XX:CMSFullGCsBeforeCompaction=0</jvm-arg><!-- 老年代占用75%进行full gc --><jvm-arg>-XX:CMSInitiatingOccupancyFraction=75</jvm-arg><jvm-arg>-XX:CMSMaxAbortablePrecleanTime=30000</jvm-arg><jvm-arg>-XX:SurvivorRatio=6</jvm-arg><jvm-arg>-XX:+PrintGCDetails</jvm-arg><jvm-arg>-XX:+PrintGCDateStamps</jvm-arg><jvm-arg>-XX:+PrintHeapAtGC</jvm-arg><jvm-arg>-Xloggc:log/gc.log</jvm-arg>

第一次优化

将Xmx和Xms设置为一样大小，调大Xmn

原因

• 将Xmx和Xms设置为一样大小，没有必要达到Xms后，再申请Xmx
• Xmn是新生代的大小，直接影响着full gc次数，如果新生代比较小，那么新生代的对象回收的就比较频繁，年龄增长很快，所以老年代很快就满了，从而导致full gc，官网建议新生代大小为整个堆的：1/4~1/2，出处： https://docs.oracle.com/javase/8/docs/technotes/tools/windows/java.html

调整以下参数

<jvm-arg>-Xmx13312m</jvm-arg><jvm-arg>-Xms13312m</jvm-arg><jvm-arg>-Xmn4096m</jvm-arg>

效果 ygc由每分钟40次，降低为10次上下 fgc时间，由之前的100ms升为300ms

第二次优化

时间一长，发现单次full gc时间太长，有时候长达2s，日志中发现pre clean没有结束，就进行了remark导致的。

 CMS: abort preclean due to time 2016-06-13T08:58:07.672+0800: 63803.570: [CMS-concurrent-abortable-preclean: 5.190/5.211 secs] [Times: user=12.15 sys=1.38, real=5.21 secs] 2016-06-13T08:58:07.677+0800: 63803.575: [GC[YG occupancy: 2652667 K (3774912 K)]63803.576: [Rescan (parallel) , 1.9969650 secs]63805.573: [weak refs processing, 0.0280880 secs] [1 CMS-remark: 7082120K(9437184K)] 9734787K(13212096K), 2.0288350 secs] [Times: user=25.39 sys=0.11, real=2.03 secs]

pre clean用于保证remark的顺利进行，如果pre clean阶段没有结束，就remark，会导致remark阶段延长，pre clean默认是5s，延长至30s。 调整以下参数：

 -XX:CMSMaxAbortablePrecleanTime=30000

效果 优化后，日发gc日志中没有abort preclean的现象发生了。

第三次优化

前两次优化已经见到效果了，但是full gc还是比较多，且持续时间比较长，增加配置，打印对象年龄：

-XX:+PrintTenuringDistribution

因为通过ygc的对象进入老年代，是按照年龄计算的，这个年龄默认是15，但是是动态调整的，所以加这个参数，再观察一下。 查看日志可以看出，对象动态调整年龄是4，太低了，对象才4岁，就进入老年代了。

2016-06-14T19:51:31.639+0800: 770.958: [GC 770.959: [ParNewDesired survivor size 214728704 bytes, new threshold 4 (max 4)- age   1:   27368432 bytes,   27368432 total- age   2:   12108344 bytes,   39476776 total- age   3:   11933416 bytes,   51410192 total- age   4:    5568312 bytes,   56978504 total

默认配置的15，怎么才4就进入老年代了，原来jvm是动态对象年龄判定的。

为了能更好地适应不同程序的内存状况，虚拟机并不总是要求对象的年龄必须达到Max Tenuring Threshold才能晋升老年代如果在Survivor空间中相同年龄所有对象大小的总和大于Survivor空间的一半，年龄大于或等于该年龄的对象就可以直接进入老年代，无须等到Max Tenuring Threshold中要求的年龄。

既然取决于survivor的大小，调大survivor

修改配置：

-Xmn5120m-XX:SurvivorRatio=6

调整后，age已经到15了。

2016-06-15T10:11:28.921+0800: 631.926: [GC 631.927: [ParNewDesired survivor size 335544320 bytes, new threshold 15 (max 15)- age   1:   44556600 bytes,   44556600 total- age   2:   41122176 bytes,   85678776 total- age   3:   14339240 bytes,  100018016 total- age   4:   19359008 bytes,  119377024 total- age   5:   13662592 bytes,  133039616 total- age   6:   21144880 bytes,  154184496 total- age   7:   17551328 bytes,  171735824 total- age   8:    5390312 bytes,  177126136 total- age   9:    8580176 bytes,  185706312 total- age  10:    7921328 bytes,  193627640 total- age  11:   17954784 bytes,  211582424 total- age  12:    6197064 bytes,  217779488 total- age  13:    7211632 bytes,  224991120 total- age  14:   10837872 bytes,  235828992 total- age  15:   10255800 bytes,  246084792 total: 4236533K->288272K(4587520K), 0.0551150 secs] 4916941K->973217K(12976128K), 0.0557070 secs] [Times: user=0.80 sys=0.01, real=0.06 secs] Heap after GC invocations=68 (full 1):

效果

• full gc由高峰期平均10分钟一次，减少到平均1小时一次
• ygc 由高峰期平均每分钟40次，减少为平均每分钟8次
• ygc由高峰期耗时由1.5s，减少为平均500ms
• 非高峰期，几乎没有full gc
• full gc高峰期耗时有所增长，由原来的不到100ms，增长为400ms，调整堆大小了嘛

参考资料

• 官方文档
• CMS GC日志详解