GC调优及awk脚本分析GC日志
原有GC参数
JAVA_OPTS="-server -XX:+UseParNewGC -Xms768m -Xmx1280m -XX:MaxNewSize=128m -XX:NewSize=128m -XX:PermSize=96m -XX:MaxPermSize=128m -XX:+UseConcMarkSweepGC -XX:+CMSPermGenSweepingEnabled -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:CMSInitiatingOccupancyFraction=1 -XX:+CMSIncrementalMode -XX:MaxTenuringThreshold=0 -XX:SurvivorRatio=20000 -XX:+UseCMSCompactAtFullCollection -XX:CMSFullGCsBeforeCompaction=0 -XX:CMSIncrementalDutyCycleMin=10 -XX:CMSIncrementalDutyCycle=30 -XX:CMSMarkStackSize=8M -XX:CMSMarkStackSizeMax=32M"
调优后的GC参数
JAVA_OPTS="-server -XX:+UseParNewGC -Xms768m -Xmx1280m -XX:MaxNewSize=128m -XX:NewSize=128m -XX:PermSize=96m -XX:MaxPermSize=128m -XX:+UseConcMarkSweepGC -XX:+CMSPermGenSweepingEnabled -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCMSCompactAtFullCollection -XX:CMSFullGCsBeforeCompaction=0 -XX:CMSMarkStackSize=8M -XX:CMSMarkStackSizeMax=32M"
原有现象：
每天有大量的CMS (concurrent mode failure)导致的Full GC.
根据网上相关文档，CMS (concurrent mode failure)的原因为当对年轻代GC时，vm估算年老代空间不足或者由于年老代内存碎片，年老代无法容纳最坏情况下的对象提升（把对象从年轻代移到年老代）而触发。
CMS GC被中断，使用Serial Collector进行Full GC。
一般的处理方式为增大年老代空间，减少年老代内存碎片。
由于原有参数中有-XX:+UseCMSCompactAtFullCollection -XX:CMSFullGCsBeforeCompaction=0，每次都会做compaction，所以推断不是内存碎片的原因。
但是观测GC日志
stdout.log.20110711.142555:26031.261: [Full GC 26031.262: [CMS (concurrent mode failure): 96426K->96441K(655360K), 0.7360040 secs] 182006K->96441K(786368K), [CMS Perm : 52050K->52028K(98304K)], 0.7362900 secs]
发现还有大量的年老代内存未使用。
同时观测到原有配置下CMS GC比较多。
原因为参数配置了 -XX:SurvivorRatio=20000，导致Survivor基本没有被使用，大量短生命对象会被移动到年老代，导致CMS GC比较多。
原来配置的策略是想让对象尽快移动到年老代，使用了iCMS GC，试图尽量降低GC对APP的影响，缩短响应时间。
但是结果导致CMS GC频繁触发。
1670.018: [GC [1 CMS-initial-mark: 92481K(655360K)] 138440K(786368K), 0.0881390 secs]
可以看到，年老代的内存还有大量空闲的时候就会触发CMS GC。
原有-XX:CMSInitiatingOccupancyFraction=1配置基本没有用。
标准CMS可以由以下2个事件触发：
1 vm经过计算认为可以触发了。
2 或者年老代空间占用比超过了CMSInitiatingOccupancyFraction。默认68%。
想让vm只被内存占用比超限触发，可以同时配置
-XX:CMSInitiatingOccupancyFraction=xx和UseCMSInitiatingOccupancyOnly选项。
同时，没有找到iCMS如何决定触发gc的时间。
根据web app的特点，短生命周期对象比较多，应该尽量让对象被minor gc回收掉。一般而言,minor gc的速度还是很快的。
综上所述，调整了GC参数，删除了iCMS的配置，调整SurvivorRatio使用默认值25。
以下为调整前后数据对比(单位为天，空为0)：
actioin = concurrent mode failure Unloading class count = 12
actioin = concurrent mode failure Unloading class count =
actioin = concurrent mode failure count = 168 time = 123.321 total_time = 493.283
actioin = concurrent mode failure count = time = total_time = 0
actioin = Full GC CMS-concurrent-mark count = 145 time = 64.492 total_time = 64.492
actioin = Full GC CMS-concurrent-mark count = time = total_time =
actioin = Full GC Unloading.class count = 10
actioin = Full GC Unloading.class count =
actioin = Full GC count = 156 time = 105.449 total_time = 421.796
actioin = Full GC count = 24 time = 17.0339 total_time = 68.1356
actioin = CMS-initial-mark count = 1560 time = 120.12 total_time = 480.479
actioin = CMS-initial-mark count = time = total_time = 0
actioin = Young GC count = 2383 time = 22.6272 total_time = 90.5086
actioin = Young GC count = 2766 time = 22.0372 total_time = 88.1487
可以看到：
GC动作concurrent mode failure Unloading class，原有每天12次左右，调整后为0.
原有concurrent mode failure导致full gc每天168次左右，耗时123.321m，调整后为0.
Full GC CMS-concurrent-mark该动作没有找到确切含义，但是也是从每天145次降到0.
Full GC Unloading.class从每天10次降为0.
Full GC从每天156次，降为24次，时间从105.449m，降到17.0339s。
单次Full GC的时间峰值没有变长。
CMS GC从每天1560，降为0,。
minor GC次数略有增大，但是时间每次minor时间减少，总时间基本保持不变。
总而言之，调整的效果还是比较好的。
经验小结：
搞清楚gc的机制。
搞不清楚的时候动手实验。
只有搞清楚了gc参数的意义并且验证了结果才配置特殊的gc参数。
写脚本分析gc日志来对比调整前后的gc运行情况。
awk脚本如下：
note:
1 由于服务器不支持“语句;语句”的形式，改为{{语句}{语句}}的形式。
2 由于服务器不支持for(init;condition;increment){语句}的形式，改为对应的while形式。
--统计gc信息 单机版本#本脚本监测GC日志，输出gc动作的次数，耗时。##startgrep [0-9][0-9][0-9]: stdout.log | awk 'BEGIN{ #常量定义{secondsInHour=3600}{secondsInDay=24*3600}{zero=0} #用户输入变量 机器核数 {cores=4} #不需要计算的，这些action都有对应的带有时间的日志输出。 #33.039: [CMS-concurrent-mark-start] #33.261: [CMS-concurrent-preclean-start] #33.270: [CMS-concurrent-abortable-preclean-start] #37.094: [CMS-concurrent-sweep-start] #37.205: [CMS-concurrent-reset-start] {ignoreList["CMS-concurrent-mark-start"]=0} {ignoreList["CMS-concurrent-preclean-start"]=0} {ignoreList["CMS-concurrent-abortable-preclean-start"]=0} {ignoreList["CMS-concurrent-sweep-start"]=0} {ignoreList["CMS-concurrent-reset-start"]=0} #number规定连续的优先级，number越小，优先级越高。 #以下每个number相同的项，定义了一个gc action。 #gc日志的关键字。可以使用正则表达式。 #{searchKey[number]="concurrent mode failure"} #输出中的文字。 #{msg[number]="concurrent mode failure"} #该动作是否有耗时，1为有，0为无。 #{hastime[number]=1} #查找时间时日志的分隔符。 #{timesperator[number]="[ ]"} #耗时所在的序位数，从1开始。 #{timeindex[number]=10} #gc是否是并发动作，1为和app并发，0为停止app，只能执行gc. #{currentactions[number]=0} # 没有什么好说的,unloading class。 {searchKey[1]="concurrent mode failure.*Unloading class"} {msg[1]="concurrent mode failure Unloading class"} {hastime[1]=0} # concurrent mode failure # The concurrent mode failure can either be avoided by increasing the tenured generation size or initiating the CMS collection at a lesser heap occupancy {searchKey[2]="concurrent mode failure"} {msg[2]="concurrent mode failure"} {hastime[2]=1} {timesperator[2]="[ ]"} {timeindex[2]=10} {currentactions[2]=0} #38182.941: [Full GC 38182.942: [CMS38183.331: [CMS-concurrent-mark: 0.390/60.394 secs] {searchKey[3]="Full.GC.*CMS-concurrent-mark"} {msg[3]="Full GC CMS-concurrent-mark"} {hastime[3]=1} {timesperator[3]="[ /]"} {timeindex[3]=7} #存疑 ??????????????????????????????????????????????????????????????? #不清楚该项是否为并发。暂定为不是并发。 {currentactions[3]=0} #unloading class #202826.209: [Full GC 202826.209: [CMS[Unloading class sun.reflect.GeneratedMethodAccessor1455] {searchKey[4]="Full.GC.*Unloading.class"} {msg[4]="Full GC Unloading.class"} {hastime[4]=0} #31312.911: [Full GC 31312.911: [CMS: 95681K->95673K(655360K), 0.6410280 secs] 132804K->95673K(786368K), [CMS Perm : 51969K->51959K(98304K)], 0.6412890 secs] {searchKey[5]="Full.GC"} {msg[5]="Full GC"} {hastime[5]=1} {timesperator[5]="[ ]"} {timeindex[5]=7} {currentactions[5]=0} #------------------------------------------------------- # CMS phase. #------------------------------------------------------- # CMS initial mark #167885.626: [GC [1 CMS-initial-mark: 106656K(655360K)] 152632K(786368K), 0.0822730 secs] {searchKey[6]="GC.*CMS-initial-mark"} {msg[6]="CMS-initial-mark"} {hastime[6]=1} {timesperator[6]="[ ]"} {timeindex[6]=7} {currentactions[6]=0} # CMS concurrent mark #0.334: [CMS-concurrent-mark: 0.077/0.079 secs] {searchKey[7]="CMS-concurrent-mark:"} {msg[7]="CMS-concurrent-mark"} {hastime[7]=1} {timesperator[7]="[ /]"} {timeindex[7]=4} {currentactions[7]=1} # CMS CMS-concurrent-preclean #170972.192: [CMS-concurrent-preclean: 0.000/0.000 secs] {searchKey[8]="CMS-concurrent-preclean:"} {msg[8]="CMS-concurrent-preclean"} {hastime[8]=1} {timesperator[8]="[ /]"} {timeindex[8]=4} {currentactions[8]=1} # CMS-concurrent-abortable-preclean #60.393: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] {searchKey[9]="CMS-concurrent-abortable-preclean:"} {msg[9]="CMS-concurrent-abortable-preclean"} {hastime[9]=1} {timesperator[9]="[ /]"} {timeindex[9]=4} {currentactions[9]=1} # CMS-remark #1040.645: [GC[YG occupancy: 67535 K (131008 K)]1040.645: [Rescan (parallel) , 0.0682420 secs]1040.713: [weak refs processing, 0.0219150 secs] [1 CMS-remark: 95660K(655360K)] 163195K(786368K), 0.0903850 secs] {searchKey[10]="CMS-remark"} {msg[10]="CMS-remark"} {hastime[10]=1} {timesperator[10]="[ ]"} {timeindex[10]=22} {currentactions[10]=0} # CMS-concurrent-sweep #42.720: [CMS-concurrent-sweep: 0.052/0.890 secs] {searchKey[11]="CMS-concurrent-sweep:"} {msg[11]="CMS-concurrent-sweep"} {hastime[11]=1} {timesperator[11]="[ /]"} {timeindex[11]=4} {currentactions[11]=1} # CMS-concurrent-reset #214.712: [CMS-concurrent-reset: 0.013/0.013 secs] {searchKey[12]="CMS-concurrent-reset:"} {msg[12]="CMS-concurrent-reset"} {hastime[12]=1} {timesperator[12]="[ /]"} {timeindex[12]=4} {currentactions[12]=1} #------------------------------------------------------- # CMS phase end. #------------------------------------------------------- # Young GC #11135.036: [GC 11135.036: [ParNew: 130944K->0K(131008K), 0.0112680 secs] 233110K->103480K(786368K), 0.0114720 secs] {searchKey[13]="GC.*ParNew"} {msg[13]="Young GC"} {hastime[13]=1} {timesperator[13]="[ ]"} {timeindex[13]=9} {currentactions[13]=0} # 计算要计数的gc action。 {maxPriority=0} for(key in searchKey) { maxPriority++ } #变量，最大日期。 {maxDay=0} #end of BEGIN }{# .的位置{dotIndex=index($0,".")}# 总秒数{seconds=zero+substr($0,1,dotIndex)}# 第几天,index from 0.{leftDaySeconds=seconds%secondsInDay}{day=(seconds-leftDaySeconds)/secondsInDay}# 第几个小时,index from 0.{leftHourSeconds=leftDaySeconds%secondsInHour}{hour=(leftDaySeconds-leftHourSeconds)/secondsInHour}# 存储最大日期。{maxDay=day}{temp=1}while(temp<=maxPriority){ if(match($0,searchKey[temp])>0) { {gcday[day , msg[temp]]++} {gchour[day,hour,msg[temp]]++} if(hastime[temp]==1) { {split($0,fields,timesperator[temp])} {gcdaytime[day,msg[temp]]+=fields[timeindex[temp]]} {gchourtime[day,msg[temp]]+=fields[timeindex[temp]]} } {next} } {temp++}}#忽略指定的gc logfor(ignoreAction in ignoreList){if(index($0,ignoreAction)>0){next}}{print $0}}END{ {temp=1} while(temp<=maxPriority) { {print "\n\n"} {temDay=maxDay} while(temDay>=0) { {timeString=""} {totalTimeString=""} if(hastime[temp]==1) { {timeString=" time = " gcdaytime[temDay,msg[temp]]} if(currentactions[temp]==0) {totalTimeString=" total_time = " gcdaytime[temDay,msg[temp]]*cores} else {totalTimeString=" total_time = " gcdaytime[temDay,msg[temp]]} } {print "actioin = " msg[temp] " count = " gcday[temDay,msg[temp]] timeString totalTimeString} {temDay--} } {temp++} } } '| less##end