[gc] 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动作的次数，耗时。

##start

grep [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 log
for(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