创建博客 登录  
 关注
   显示下一条  |  关闭

wwyinhuabin的博客

在你确认一个问题的时候 首先想想怎么去验证他

 
 
 

日志

 
 

JAVA JVM GC LOG分析和调优【转】  

2010-09-09 22:55:48|  分类: java 性能 |  标签: |字号 订阅

在大型的java运用中,要进行程序调优,指定一个合适的垃圾回收机制是必不可少的,那如何可确定某gc是否使得程序最优化呢?我们可以查看jvm打印出 的gc日志来分析,并做出进一步优化,而目前并没有一篇文章明确的指明java中各种gc算法打印出日志的格式,以及如何阅读。所以接下来本文将试着边介 绍各种垃圾回收机制边解释该回收机制下log的格式。
1,垃圾收集算法
1.1 引用计数法(Reference Counting Collector)
系统记 录对象被应用的次数,当应用次数为0时,就可以将该对象所占内存回收。该算法可以不用暂停运用,但缺点是无法解决重复运用的问题。所以java并没有提供 此类垃圾回收器。
1.2  tracing算法(Tracing Collector) 
tracing算法的垃圾收集器从根集开始扫描,识别出哪些对象可达,哪 些对象不可达,并用某种方式标记可达对象。
1.2.1 复制 ( Copying )算法
复制算法将堆等分成2个区域,一个区域含有现在的数据对象(ToSpace),而另一个区域包含废 弃的数据(FromSpace)。复制算法将存活的对象从FromSpace复制到ToSpace,然后切换Fromspace和ToSpace的指针, 以前的FromSpace变为现在的ToSpace区域。
  1.2.2 标记-整理( Mark-Compact )算法

  1.2.3 标记-清除(Mark-Sweep) 

Using the -XX flags for our collectors for jdk6, 
  • UseSerialGC is "Serial" + "Serial Old"
  • UseParNewGC is "ParNew" + "Serial Old"
  • UseConcMarkSweepGC is "ParNew" + "CMS" + "Serial Old". "CMS" is used most of the time to collect the tenured generation. "Serial Old" is used when a concurrent mode failure occurs.
  • UseParallelGC is "Parallel Scavenge" + "Serial Old"
  • UseParallelOldGC is "Parallel Scavenge" + "Parallel Old" 

 

SerailGC

1,Serial Young GC  
0.246: [GC 0.246: [DefNew: 1403K->105K(1984K), 0.0109275 secs] 1403K->1277K(6080K), 0.0110143 secs]  
2, Serial Olg Gc

1.133: [GC 1.133: [DefNew: 960K->64K(960K), 0.0012208 secs]1.135: [Tenured: 7334K->7142K(7424K), 0.0213756 secs] 7884K->7142K(8384K), [Perm : 364K->364K(12288K)], 0.0226997 secs] [Times: user=0.01 sys=0.00, real=0.02 secs] 

 

Parrallel GC serailGC的适应muti Core的加强版,就是在minorGC时候采用并行的进行收集,而fullGC并没有改变 

Parralllel Compacting GC 在parrallelGC的基础上将fullgc也变为并发的了
With the parallel compacting collector, the old and permanent generations are collected in a stop-theworld,mostly parallel fashion with sliding compaction. The collector utilizes three phases. First, each generation is logically divided into fixed-sized regions. In the marking phase, the initial set of live objects directly reachable from the application code is divided among garbage collection threads, and then all live objects are marked in parallel. As an object is identified as live, the data for the region it is in is updated with information about the size and location of the object.备注 待翻译

 

Concurrent Mark-Sweep (CMS) Collector   有一种需求是应用的相应时间比应用的吞吐重要,为了满足这种需求,jvm提供了该场景下的垃圾收集器CMS,使用该垃圾收集器的时候minorGC和 ParralelGC当中采用的一样,只是在老生代更换了不同的算法。

CMS将老生代的回收分为4个阶段 其中只有2个阶段是要stop-the-world的,而其余阶段是不需要的,因此降低了系统暂停时间,缺点是在其余的2个阶段会更应用抢jvm资源。

 
JAVA JVM GC LOG分析和调优【转】 - wwyinhuabin - wwyinhuabin的博客
  

从上图可以看出,CMS的运 行过程。

A collection cycle for the CMS collector starts with a short pause, called the initial mark, that
identifies the initial set of live objects directly reachable from the application code. Then,
during the concurrent marking phase, the collector marks all live objects that are transitively
reachable from this set. Because the application is running and updating reference fields while the marking phase is taking place, not all live objects are guaranteed to be marked at the end of the concurrent marking phase. To handle this, the application stops again for a second pause, called remark, which finalizes marking by revisiting any objects that were modified during the concurrent marking phase. Because the remark pause is more substantial than the initial mark, multiple threads are run in parallel to increase its efficiency. 备注 待翻译


Concurrent Mark-Sweep GC log format:



Full GC 被调用的出现情况 
 

promotion failed( mark-sweep-compact stop-the-world ) ParNew (promotion failed):  当老生代空闲空间存在碎片,导致没有足够大的连续空间开存放新生代对象的升级时,机会触发promotion failed。此时调用一个Mark-Compact 垃圾收集器是很有必要的。(默认采用 Serial Old GC)

106.641: [GC 106.641: [ParNew (promotion failed): 14784K->14784K(14784K), 0.0370328 secs]106.678: [CMS106.715: [CMS-concurrent-mark: 0.065/0.103 secs] [Times: user=0.17 sys=0.00, real=0.11 secs] 
 (concurrent mode failure): 41568K->27787K(49152K), 0.2128504 secs] 52402K->27787K(63936K), [CMS Perm : 2086K->2086K(12288K)], 0.2499776 secs] [Times: user=0.28 sys=0.00, real=0.25 secs] 

full promotion guarantee failure ( concurrent mode failure ): 当垃圾回收算法预测在下一次Conc-Mark-Sweep算法调用之前,老生代的空余空间将会被系统占用光。为了解决这一问题,垃 圾回收算法进入conccurent mode failure状态,调用一个 stop-the-world(serail Old GC)来清理系统Heap。


eg:为了触发这种情况 我们先分配64m内存给jvm,然后新生代和老年代的占用比例为7,即老年代用了7*8=58 触 发concurrent mode failure的情况:

 

 

public class FullPromotionGuaranteeFailure
{
public static void main(String[] args)
{
List<byte[]> bytesList = new ArrayList<byte[]>();
for (int i = 0; i < 7 * 8 * 1024; i++)
{
bytesList.add(new byte[1024]);
}

//bytesList = null; 没有必要的 gc会知道函数里面变量是否还会被引用
byte[] bytes = new byte[16 * 1024 * 1024];
String.valueOf(bytes[0]);
}
}

1 资料

2 GC日志打印

  GC调优是个很实验很伽利略的活儿,GC日志是先决的数据参考和最终验证:

-XX:+PrintGCDetails -XX:+PrintGCTimeStamps(GC发生的时间) -XX:+PrintGCApplicationStoppedTime(GC消耗了多少时间) -XX:+PrintGCApplicationConcurrentTime(GC之间运行了多少时间)

 

3 收集器选择

CMS收集器:暂停时间优先

   配置参数:-XX:+UseConcMarkSweepGC
已默认无需配置的参数:-XX:+UseParNewGC(Parallel收集新生代) -XX:+CMSPermGenSweepingEnabled(CMS收集持久代) -XX:UseCMSCompactAtFullCollection(full gc时压缩年老代)

   初始效果:1g堆内存的新生代约60m,minor gc约5-20毫秒,full gc约130毫秒。

Parallel收集器:吞吐量优先

    配置参数: -XX:+UseParallelGC -XX:+UseParallelOldGC(Parallel收集年老代,从JDK6.0开始支持)

    已默认无需配置的参数: -XX:+UseAdaptiveSizePolicy(动态调整新生代大小)

    初始效果:1g堆内存的新生代约90-110m(动态调整),minor gc约5-20毫秒,full gc有无UseParallelOldGC 参数分别为1.3/1.1秒,差别不大。

    另外-XX:MaxGCPauseMillis=100 设置minor gc的期望最大时间,JVM会以此来调整新生代的大小,但在此测试环境中对象死的太快,此参数作用不大。

4 调优实战

      Parallel收集高达1秒的暂停时间基本不可忍受,所以选择CMS收集器。

      在被压测的Mule 2.0应用里,每秒都有大约400M的海量短命对象产生:

  1. 因为默认60M的新生代太小了,频繁发生minor gc,大约0.2秒就进行一次。
  2. 因为CMS收集器中MaxTenuringThreshold(生代对象撑过过多少次minor gc才进入年老代的设置)默认0,存活的临时对象不经过Survivor区直接进入年老代,不久就占满年老代发生full gc。

     对这两个参数的调优,既要改善上面两种情况,又要避免新生代过大,复制次数过多造成minor gc的暂停时间过长。

  1. 使用-Xmn调到1/3 总内存。观察后设置-Xmn500M,新生代实际约460m。(用-XX:NewRatio设置无效,只能用 -Xmn)。
  2. 添加-XX:+PrintTenuringDistribution 参数观察各个Age的对象总大小,观察后设置-XX:MaxTenuringThreshold=5。

      优化后,大约1.1秒才发生一次minor gc,且速度依然保持在15-20ms之间。同时年老代的增长速度大大减缓,很久才发生一次full gc,

      参数定稿:

 -server -Xms1024m -Xmx1024m -Xmn500m -XX:+UseConcMarkSweepGC   -XX:MaxTenuringThreshold=5  -XX:+ExplicitGCInvokesConcurrent

 

      最后服务处理速度从1180 tps 上升到1380 tps,调整两个参数提升17%的性能还是笔很划算的买卖。

 

     另外,JDK6 Update 7自带了一个VisualVM工具,内里就是之前也有用过的Netbean Profiler,类似JConsole一样使用,可以看到线程状态,内存中对象以及方法的CPU时间等调优重要参考依据。免费捆绑啊,Sun 这样搞法,其他做Profiler的公司要关门了。

使用sh脚本来监控gc日志

Java代码
  1. cd /usr/local/apache/htdocs/SoapMmsService/logs  
  2. more gc.log | grep "eden space" > test.log  
  3. content=`sed -n '$'p test.log`  
  4. percent=`sed -n '$'p test.log | awk '{print $4}' | awk -F% '{print $1}'`  
  5. echo $percent  
  6. base=0  
  7. echo $base  
  8. maxcount=98  
  9. if test $percent -gt $base; then  
  10. if test $percent -lt $maxcount; then  
  11. echo "test"  
  12. wget "http://127.0.0.1:6666/control" >tmp  
  13. fi  
  14. fi  


当gc中的日志出现异常.通知一个web接口.这个接口目前可以利用公司资源可以用短信做提示.如果没有这个,可以这里实现重启之类的操作.

  评论这张
转发至微博
转发至微博
0   分享到:        
阅读(623)| 评论(0)| 引用 (0) |举报

历史上的今天

相关文章

最近读者

评论

<#--最新日志,群博日志--> <#--推荐日志--> <#--引用记录--> <#--博主推荐--> <#--随机阅读--> <#--首页推荐--> <#--相关文章--> <#--历史上的今天--> <#--右边模块结构--> <#--评论模块结构--> <#--引用模块结构--> <#--博主发起的投票-->
 
 
 
 
 
 
 
 
 
 
 
 
 
 

页脚

网易公司版权所有 ©1997-2012