摘要
如果你的服务日志卡住了,请求不处理了,可能是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: [ParNew
Desired 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: [ParNew
Desired 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,调整堆大小了嘛