某应用的GC调优总结前期工作统计应用数据(峰值TPS、平均TPS,每秒平均分配内存大小、每个请求的平均分配内存
某应用的GC调优总结
前期工作
统计应用数据(峰值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日志:
分析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
第六轮调优上面的调优保持系统稳定运行了很长时间后,突然有一台机器出现大量Full GC,观察gc.log发现是由于持久带满造成的:
引用[CMS Perm : 131055K->52158K(131072K)], 30.1112560 secs]
应对的方法为加大持久带,并让持久带也使用CMSGC方式回收:
引用修改:
-XX:PermSize=64m -> -XX:PermSize=200m
-XX:MaxPermSize=128m -> -XX:MaxPermSize=200m
增加:
-XX:+CMSClassUnloadingEnabled
另外,对于持久带满的观测方法,可以参考Rednaxelafx给我的回答:
http://hllvm.group.iteye.com/group/topic/28379
优化后的整体参数引用
<jvm-arg>-Xmx13000m</jvm-arg>
<jvm-arg>-Xms13000m</jvm-arg>
<jvm-arg>-Xmn7020m</jvm-arg>
<jvm-arg>-Xss256k</jvm-arg>
<jvm-arg>-XX:PermSize=200m</jvm-arg>
<jvm-arg>-XX:MaxPermSize=200m</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>-XX:+CMSClassUnloadingEnabled</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>
参考资料http://my.oschina.net/shootercn/blog/15393http://blog.bluedavy.com/?p=200http://blog.bluedavy.com/?p=70http://blog.bluedavy.com/?p=45http://blogs.oracle.com/poonam/entry/understanding_cms_gc_logshttp://java.sun.com/j2se/reference/whitepapers/memorymanagement_whitepaper.pdfJava 6 JVM参数选项大全(中文版)《分布式Java应用 基础与实践》