某应用的GC调优总结_JAVA

您所在的位置：程序员俱乐部 > 编程开发 > JAVA > 某应用的GC调优总结

某应用的GC调优总结

2011/10/18 6:10:48 blueswind8306 http://blueswind8306.iteye.com 我要评论(0)

摘要：前期工作统计应用数据（峰值TPS、平均TPS，每秒平均分配内存大小、每个请求的平均分配内存大小）统计GC分配、回收内存的数据（MinorGC、FullGC停顿时长，平均多长时间触发一次GC，每次Eden->Old的平均晋升大小等）搭建压力测试环境模拟线上真实用户行为及相应压力（记录用户访问的accesslog作为压力测试源，使用的压力测试软件为http_load和httperf）第一轮调优尝试使用JDK7的G1回收，在安装GDK7时失败，原因是操作系统版本必须是RedHat5
标签：总结应用调优

前期工作

统计应用数据（峰值TPS、平均TPS，每秒平均分配内存大小、每个请求的平均分配内存大小）
统计GC分配、回收内存的数据（MinorGC、FullGC停顿时长，平均多长时间触发一次GC，每次Eden->Old的平均晋升大小等）
搭建压力测试环境
模拟线上真实用户行为及相应压力（记录用户访问的accesslog作为压力测试源，使用的压力测试软件为http_load和httperf）

第一轮调优

尝试使用JDK7的G1回收，在安装GDK7时失败，原因是操作系统版本必须是RedHat 5.5+/CentOS 5.5+(http://www.oracle.com/technetwork/java/javase/config-417990.html#os) 暂时不准备升级操作系统，所以放弃JDK7 G1。
改为使用JDK6 Update26版本的G1回收。设置最大回收时间为40ms，通过12小时的观察，发现有大量超时，感觉G1在JDK6上还不够成熟，所以决定暂时放弃G1，改为ParallelGC。
使用ParallelGC后，压力测试发现每次MinorGC的耗时降低到40ms左右（以前是200ms以上），但每隔3小时就会有一次FullGC发生，每次FullGC耗时3~4秒。
由于FullGC造成的应用暂停在这个应用中是不能接受的。所以放弃ParallelGC，改为使用CMSGC。

第二轮调优

观察gcutil发现PermSpace接近100%，所以调大PermSize和MaxPermSize。
调整-Xms和-Xmx相等（如果Xms小于Xmx，则应用启动初期老生代相对较小，会导致CMS GC更加频繁）
尝试优化每次ParNew的时长（优化前每次在200ms以上）：增加“-XX:+PrintTenuringDistribution”参数观察gc.log，发现对象在SurvivorSpace中的age过多，会导致大量老对象在新生代无法晋升到老生代。而JVM在ParNewGC时分析这些老对象的引用关系是非常耗时的。观察MaxTenuringThreshold和TargetSurvivorRatio设置的过大，所以将MaxTenuringThreshold值调小为15即达到优化目的（优化后每次ParNew在20~40ms之间）。并且为了提高SurvivorSpace的利用率，将TargetSurvivorRatio设置为100（代表强制GC关闭动态调整MaxTenuringThreshold）。参考：http://blog.bluedavy.com/?p=70
尝试优化ParNew之间的间隔时间（优化前3~4秒一次）：观察gc.log发现每次ParNew后大约有不到780MB的存留对象，希望这些对象尽量活在SurvivorSpace里，并且同时又要保证ParNew的时间间隔，所以在Xmx和SurvivorRatio不变的情况下，将Xmn扩大到7800MB。（因为SurvivorRatio=8，所以整个EdenSpace需要780*10=7800MB）
再次观察优化后的GC情况（gcutil），发现由于大量对象都在EdenSpace消亡，所以OldGen的晋升比率极低（0.01%~0.02%），所以可以考虑增大CMSInitiatingOccupancyFraction以提高OldGen的利用率，降低CMS GC的触发频率（增大到80%）。
去掉CMSFullGCsBeforeCompaction（去掉后默认为0，表示每次FullGC后都会进行压缩碎片整理）。因为CMS GC导致的内存碎片必须清除，否则OldGen的利用率会降低。

第三轮调优

运营一段时间后，发现CMSGC超过一秒的情况非常多（图中箭头指向）：

分析gc日志：
引用446600.708: [CMS-concurrent-preclean-start]
446600.788: [CMS-concurrent-preclean: 0.072/0.080 secs] [Times: user=0.60 sys=0.03, real=0.08 secs]
446600.788: [CMS-concurrent-abortable-preclean-start]
446603.594: [GC 446603.594: [ParNew: 6447479K->65869K(7188480K), 0.0634720 secs] 10708889K->4328064K(12513280K), 0.0638340 secs] [Times: user=0.42 sys=0.01, real=0.06 secs]
446605.980: [CMS-concurrent-abortable-preclean: 5.107/5.192 secs] [Times: user=34.46 sys=2.73, real=5.19 secs]
446605.982: [GC[YG occupancy: 4313641 K (7188480 K)]446605.982: [Rescan (parallel) , 1.5739870 secs]446607.556: [weak refs processing, 0.0172470 secs] [1 CMS-remark: 4262195K(5324800K)] 8575836K(12513280K), 1.5920360 secs] [Times: user=12.46 sys=0.05, real=1.59 secs]

可以看出，在remark中的Rescan阶段耗费了1.57秒，并且这个过程是会导致应用暂停的。问题定位在了Rescan阶段。
发现在Rescan时新生代过大（4313641 K (7188480 K)），是导致Rescan慢的关键原因，如果能尽量保持新生代很小的时候就终止preclean阶段，就可以控制住在Rescan时新生代的大小。查看JVM参数发现-XX:CMSScheduleRemarkEdenPenetration的意思是当新生代存活对象占EdenSpace的比例超过多少时，终止preclean阶段并进入remark阶段。这个参数的默认值是50%，按照现在的配置，就是7800m*50%=3900m左右，所以更改此参数设置为：

引用-XX:CMSScheduleRemarkEdenPenetration=1

进行压力测试，发现remark阶段的耗时确实降低了不少，说明优化有效。

第四轮调优

运行几天后观察gc日志（2011-09-05），发现每隔100000秒的CMSGC的峰值情况确实大大降低了，但是还是偶尔有超过1~2秒的CMSGC情况：

分析GC日志:

引用
115810.496: [GC 115810.496: [ParNew: 6429866K->40505K(7188480K), 0.0417220 secs] 10689519K->4301475K(12513280K), 0.0419300 secs] [Times: user=0.28 sys=0.00, real=0.04 secs]
115810.539: [GC [1 CMS-initial-mark: 4260969K(5324800K)] 4301537K(12513280K), 0.0501400 secs] [Times: user=0.05 sys=0.00, real=0.05 secs]
115810.589: [CMS-concurrent-mark-start]
115811.859: [CMS-concurrent-mark: 1.270/1.270 secs] [Times: user=7.67 sys=0.32, real=1.27 secs]
115811.859: [CMS-concurrent-preclean-start]
115811.888: [CMS-concurrent-preclean: 0.028/0.029 secs] [Times: user=0.09 sys=0.00, real=0.03 secs]
115811.889: [CMS-concurrent-abortable-preclean-start]
CMS: abort preclean due to time 115821.992: [CMS-concurrent-abortable-preclean: 10.082/10.104 secs] [Times: user=19.25 sys=1.66, real=10.10 secs]
115821.994: [GC[YG occupancy: 4298926 K (7188480 K)]115821.994: [Rescan (parallel) , 2.5039100 secs]115824.498: [weak refs processing, 0.0283980 secs] [1 CMS-remark: 4260969K(5324800K)] 8559896K(12513280K), 2.5327520 secs] [Times: user=19.77 sys=0.13, real=2.53 secs]
115824.527: [CMS-concurrent-sweep-start]
115827.733: [GC 115827.733: [ParNew: 6430265K->61593K(7188480K), 0.0522130 secs] 9504296K->3136946K(12513280K), 0.0525360 secs] [Times: user=0.34 sys=0.00, real=0.05 secs]

发现concurrent-abortable-preclean阶段超过了-XX:CMSMaxAbortablePrecleanTime设置的最大值10秒，所以强制终止了preclean阶段而进入remark阶段。而这段时间的两次ParNew之间的间隔了17秒之多。希望的是在preclean阶段产生一次MinorGC，所以将preclean的最大时长调整为30秒：

引用-XX:CMSMaxAbortablePrecleanTime=30000

第五轮调优

运行一段时间后，发现居然出现了FullGC，大概在3~5天左右出现一次，以下是FullGC时的日志：

引用443299.787: [GC 443299.787: [ParNew: 6438755K->59103K(7188480K), 0.0645650 secs] 10305335K->3927053K(12513280K), 0.0648090 secs] [Times: user=0.42 sys=0.01, real=0.07 secs]
43305.129: [GC 443305.129: [ParNew: 6448863K->50788K(7188480K), 0.0652490 secs] 10316813K->3919611K(12513280K), 0.0654960 secs] [Times: user=0.43 sys=0.00, real=0.07 secs]
443310.292: [GC 443310.292: [ParNew (promotion failed): 6440548K->6451166K(7188480K), 2.0562820 secs]443312.348: [CMS: 3871691K->1352176K(5324800K), 17.0114770 secs] 10309371K->1352176K(12513280K), [CMS Perm : 86559K->53644K(131072K)], 19.0681060 secs] [Times: user=17.52 sys=0.04, real=19.07 secs]
443357.642: [GC 443357.642: [ParNew: 6389760K->49312K(7188480K), 0.1196360 secs] 7741936K->1401489K(12513280K), 0.1198690 secs] [Times: user=0.80 sys=0.01, real=0.12 secs]
443362.586: [GC 443362.586: [ParNew: 6439072K->52114K(7188480K), 0.0622160 secs] 7791249K->1404290K(12513280K), 0.0624640 secs] [Times: user=0.43 sys=0.01, real=0.06 secs]

发现在443310秒有promotion failed出现（新生代晋升到老生代空间不足导致的FullGC），但是此时的OldGen可以算出还剩1.45G的空间（5324800K-3871691K=1453109K），而根据gcLogViewer的统计，每次MinorGC后平均新生代晋升到老生代的内存大小仅为58K。所以并不是OldGen空间不够，而是OldGen的连续空间不够造成的promotion failed。
换句话说，是由于OldGen在距离上次CMSGC后，又产生了大量内存碎片，当某个时间点在OldGen中的连续空间没有一块足够58K的话，就会导致的promotion failed。以下是Sun针对这个问题的说明：
引用Sometimes we see these promotion failures even when the logs show that there is enough free space in tenured generation. The reason is 'fragmentation' - the free space available in tenured generation is not contiguous, and promotions from young generation require a contiguous free block to be available in tenured generation. CMS collector is a non-compacting collector, so can cause fragmentation of space for some type of applications. In his blog, Jon talks in detail on how to deal with this fragmentation problem:
http://blogs.oracle.com/roller-ui/bsc/spider.jsp?entry=c885fd8e0927816c010927b86d0c0603
或者参考我的另一篇blog：http://blueswind8306.iteye.com/admin/blogs/1194773
考虑如果能够缩短CMSGC的周期，保证在出现promotion failed之前就进行CMSGC，就可以避免这个问题了。所以考虑将新生代空间缩小（相对来说就增加了老生代的空间），并且将CMSGC触发比率降低，同时保证Survivor空间不变。所以优化参数改动如下：

引用-Xmn7800m -> -Xmn7020m
-XX:SurvivorRatio=8 –> -XX:SurvivorRatio=7
-XX:CMSInitiatingOccupancyFraction=80 -> -XX:CMSInitiatingOccupancyFraction=70

优化后的整体参数
引用
<jvm-arg>-Xmx13000m</jvm-arg>
<jvm-arg>-Xms13000m</jvm-arg>
<jvm-arg>-Xmn7020m</jvm-arg>
<jvm-arg>-Xss256k</jvm-arg>
<jvm-arg>-XX:PermSize=64m</jvm-arg>
<jvm-arg>-XX:MaxPermSize=128m</jvm-arg>
<jvm-arg>-XX:ParallelGCThreads=20</jvm-arg>
<jvm-arg>-XX:+UseConcMarkSweepGC</jvm-arg>
<jvm-arg>-XX:+UseParNewGC</jvm-arg>
<jvm-arg>-XX:SurvivorRatio=7</jvm-arg>
<jvm-arg>-XX:TargetSurvivorRatio=100</jvm-arg>
<jvm-arg>-XX:MaxTenuringThreshold=15</jvm-arg>
<jvm-arg>-XX:CMSInitiatingOccupancyFraction=70</jvm-arg>
<jvm-arg>-XX:SoftRefLRUPolicyMSPerMB=0</jvm-arg>
<jvm-arg>-XX:+UseCMSCompactAtFullCollection</jvm-arg>
<jvm-arg>-XX:CMSMaxAbortablePrecleanTime=30000</jvm-arg>
<jvm-arg>-XX:CMSScheduleRemarkEdenPenetration=1</jvm-arg>
<jvm-arg>-server</jvm-arg>
<jvm-arg>-XX:+PrintGCDetails</jvm-arg>
<jvm-arg>-XX:+PrintGCDateStamps</jvm-arg>
<jvm-arg>-Xloggc:./log/gc.log</jvm-arg>

参考资料