`
zhang_xzhi_xjtu
  • 浏览: 538371 次
  • 性别: Icon_minigender_1
  • 来自: 杭州
社区版块
存档分类
最新评论

[gc] GC调优及awk脚本分析GC日志

    博客分类:
  • java
 
阅读更多
原有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









分享到:
评论

相关推荐

    java高级面试题.zip

    面试中可能还会涉及到类加载机制、JVM调优工具(如JVisualVM、JConsole)以及如何分析和解决内存泄漏问题。 Redis作为一款高性能的键值存储系统,在面试中常被问到其数据类型(String、Hash、List、Set、Sorted Set...

    Linux shell脚本实现CPU预警

    - 初始化脚本执行环境,包括获取初始CPU空闲率及创建日志存储目录。 2. **主循环**: ```bash count=0 condition=true while $condition; do if [ $cpu_idle -le 20 ]; then # 处理CPU高负载逻辑 else # ...

    使用算法熵 分析 DNA 序列(Kolmogorov 复杂度)_shell_代码_下载

    这些脚本通常使用bash语言编写,利用Unix/Linux系统中的命令行工具,如awk、sed、grep等,以及可能的生物信息学库来处理DNA序列数据。 总的来说,通过Shell脚本和算法熵分析DNA序列,我们可以获得有关序列复杂性的...

    Linux利用Shell脚本部署jar包项目的完整步骤

    在Linux环境中,自动化部署Java应用程序通常使用Shell脚本来实现,特别是对于包含jar包的应用,这种方法既高效又方便。本文将详细介绍如何使用Shell脚本在Linux上部署jar包项目。 首先,确保你的系统已经安装了Java...

    一键备份gitolite服务器的Shell脚本

    如果本地已经有仓库的镜像,脚本会进入该目录并执行`git remote update`来获取最新的远程分支和标签,然后运行`git gc`进行垃圾回收,优化本地存储。 这个脚本适用于系统管理员或团队负责人,他们需要定期备份...

    记一次tomcat进程cpu占用过高的问题排查记录

    3. **线程CPU使用量分析**:在Linux环境下,可以通过自定义脚本结合`ps`、`awk`等命令来分析每个线程的CPU使用情况,帮助定位问题。 4. **JVM内存和GC监控**:`jstat -gc`命令用于查看JVM的内存使用和垃圾回收情况...

    百度面试题 shell

    综上所述,通过对这些面试题的解析,我们不仅能够了解到Shell脚本编程的基础知识,还能掌握一些高级特性,如并发处理、日志数据分析、信号处理等,这对于提升Shell脚本编程技能是非常有帮助的。

    java面试题,命令大全!

    10. **其他**:Junit测试框架,Maven或Gradle构建工具,性能调优,日志框架(Log4j、SLF4J),以及代码版本控制(Git)等。 然后,Linux命令是开发者必备的技能,尤其在服务器管理和运维中。`Linux命令大全(修改版)...

    python和shell监控linux服务器的详细代码

    - **脚本示例**:`loard_monitor.sh`中,首先获取服务器的IP地址,然后利用`grep`和`awk`命令获取CPU核心数以及15分钟的平均负载值。接下来,计算单个核心的平均负载,如果超过1.0,则执行邮件告警。 2. **Python...

    vim快捷键使用说明

    Vim是一款强大的文本编辑器,在Linux及Unix系统中被广泛使用。它具有丰富的功能和高度的可定制性,支持多种编程语言,是学习Linux编程不可或缺的工具之一。本文将详细介绍VIM的一些常用快捷键及其应用场景,帮助用户...

Global site tag (gtag.js) - Google Analytics