一次CMS GC问题排查过程(理解原理+读懂GC日志)

标签: cms gc 问题 | 发表时间:2013-12-14 22:21 | 作者:
出处:http://www.iteye.com

这个是之前处理过的一个线上问题,处理过程断断续续,经历了两周多的时间,中间各种尝试,总结如下。这篇文章分三部分:

1、问题的场景和处理过程;2、GC的一些理论东西;3、看懂GC的日志

先说一下问题吧

问题场景:线上机器在半夜会推送一个700M左右的数据,这个时候有个数据置换的过程,也就是说有700M*2的数据在heap区域中,线上系统超时比较多,导致了很严重(严重程度就不说了)的问题。

问题原因:看日志,系统接口超时的时候,系统出现了FullGC,这个时候stop-the-world了,也就停机了。分析gc的日志,发现有promotion failed,根据FullGC触发的条件,这个时候就会出现FullGC了。日志如下:

1
2
2013 - 11 -27T03: 00 : 53.638 + 0800 35333.562 : [GC  35333.562 : [ParNew (promotion failed): 1877376K->1877376K(1877376K),  15.7989680  secs] 35349.361 : [CMS: 2144171K->2129287K(2146304K),  10.4200280  sec
s] 3514052K->2129287K(4023680K), [CMS Perm : 119979K->118652K(190132K)],  26.2193500  secs] [Times: user= 30.35  sys= 5.19 , real= 26.22  secs]

问题解决:中间调整过几次,先搞了几台机器做了验证,后来逐步推广的。

1、调大heap区,由原来的4g,调整到5g,young区的大小不变,还是2g,这时候old区就由2g变为3g了(这样保证old区有足够的空间);

2、设置-XX:UseCMSInitiatingOccupancyOnly,其实这个不关这个问题,只是发现半夜CMS进行的有点频繁,就禁止掉了悲观策略;

3、设置CMS区回收的比例,从80%调整到75%,让old区尽早的进行,有足够的空间剩余;

 

为什么要有GC(垃圾回收)?

JVM通过GC来回收堆和方法区中的内存,GC的基本原理就是找到程序中不再被使用的对象,然后回收掉这些对象占用的内存。

 

主要的收集器有哪些?

引用计数器和跟踪计数器两种。

引用计数器记录对象是否被引用,当计数器为零时,说明对象已经不再被使用,可以进行回收。java中的对象有复杂的引用关系,不是很适合引用计数器,所以sun jdk中并没有实现这种GC方式。

跟踪收集器,全局记录数据的引用状态,基于一定的条件触发。执行的时候,从根集合开始扫描对象的引用关系,主要有复制(copying)、标记-清除(Mark-Sweep)、标记-压缩(Mark-Compact)那种算法。

 

跟踪计数器的三种算法简介?

复制:从根集合搜扫描出存活的对象,然后将存活的对象复制到一块新的未使用的空间中,当要回收的空间中存活的对象较少时,比较高效;

标记清除:从根集合开始扫描,对存活的对象进行标记,比较完毕后,再扫描整个空间中未标记的对象,然后进行回收,不需要对对象进行移动;

标记压缩:标记形式和“标记清除”一样,但是回收不存活的对象后,会把所有存活的对象在内存空间中进行移动,好处是减少了内存碎片,缺点是成本比较高;

 

java内存区域的形式是啥样的?

这里就不再介绍了,之前有一篇文章中专门介绍这个的( http://iamzhongyong.iteye.com/blog/1333100)。

 

新生代可用的GC?

新生代中对象存活的时间比较短,因此给予Copying算法实现,Eden区域存放新创建的对象,S0和S1区其中一块用于存放在Minor GC的时候作为复制存活对象的目标空间,另外一块清空。

串行GC(Serial GC)比较适合单CPU的情况,可以通过-XX:UseSerialGC来强行制定;

并行回收GC(Parallel Scavenge),启动的时候按照设置的参数来划定Eden/S0/S1区域的大小,但是在运行时,会根据Minor GC的频率、消耗时间来动态调整三个区域的大小,可以用过-XX:UseAdaptiveSizePolicy来固定大小,不进行动态调整;

并行GC(ParNew)划分Eden、S1、S0的区域上和串行GC一样。并行GC需要配合旧生代使用CMS GC(这是他和并行回收GC的不同)(如果配置了CMS GC的方式,那么新生代默认采取的就是并行GC的方式);

 

啥时候会触发Minor GC?

当Eden区域分配内存时,发现空间不足,JVM就会触发Minor GC,程序中System.gc()也可以来触发。

 

旧生代可用的GC方式有哪几种?

串行GC(Serial MSC)、并行GC(Parallel MSC)、并发GC(CMS);

 

关于CMS?

采用CMS时候,新生代必须使用Serial GC或者ParNew GC两种。CMS共有七个步骤,只有Initial Marking和Final Marking两个阶段是stop-the-world的,其他步骤均和应用并行进行。持久代的GC也采用CMS,通过-XX:CMSPermGenSweepingEnabled -XX:CMSClassUnloadingEnabled来制定。在采用cms gc的情况下,ygc变慢的原因通常是由于old gen出现了大量的碎片。

 

为啥CMS会有内存碎片,如何避免?

由于在CMS的回收步骤中,没有对内存进行压缩,所以会有内存碎片出现,CMS提供了一个整理碎片的功能,通过-XX:UseCompactAtFullCollection来启动此功能,启动这个功能后,默认每次执行Full GC的时候会进行整理(也可以通过-XX:CMSFullGCsBeforeCompaction=n来制定多少次Full GC之后来执行整理),整理碎片会stop-the-world.

 

啥时候会触发CMS GC?

1、旧生代或者持久代已经使用的空间达到设定的百分比时(CMSInitiatingOccupancyFraction这个设置old区,perm区也可以设置);

2、JVM自动触发(JVM的动态策略,也就是悲观策略)(基于之前GC的频率以及旧生代的增长趋势来评估决定什么时候开始执行),如果不希望JVM自行决定,可以通过-XX:UseCMSInitiatingOccupancyOnly=true来制定;

3、设置了 -XX:CMSClassUnloadingE考虑nabled 这个则考虑Perm区;

 

啥时候会触发Full GC?

一、旧生代空间不足:java.lang.outOfMemoryError:java heap space;

二、Perm空间满:java.lang.outOfMemoryError:PermGen space;

三、CMS GC时出现promotion failed  和concurrent  mode failure(Concurrent mode failure发生的原因一般是CMS正在进行,但是由于old区内存不足,需要尽快回收old区里面的死的java对象,这个时候foreground gc需要被触发,停止所有的java线程,同时终止CMS,直接进行MSC。);

四、统计得到的minor GC晋升到旧生代的平均大小大于旧生代的剩余空间;

五、主动触发Full GC(执行jmap -histo:live [pid])来避免碎片问题;

 

为啥heap小于3g不建议使用CMS GC这种方式?

http://hellojava.info/?p=142 毕大师的这篇文章讲的很清楚。

1、触发比例不好设置,设置大了,那么剩余的空间就少了很多,设置小了,那old区还没放置多少东西,就要进行回收了;

2、CMS进行的时候,是并行的,也就意味着如果过于频繁的话,会和应用的强占CPU;

3、CMS会有内存 碎片问题;

4、YGC的速率变慢(由于CMS GC的实现原理,导致对象从新生代晋升到旧生代时,寻找哪里能放下的这个步骤比ParallelOld GC是慢一些的,因此就导致了YGC速度会有一定程度的下降。);

 

JVM的悲观策略是啥?

所谓的悲观策略( http://tmalltesting.com/archives/663 我们性能测试团队一个同学分析的案例),就是JVM不按照JVM指定的参数来进行CMS GC,而是根据内存情况以及之前回收的方式动态调整,自行进行GC。旧生代剩余的空间(available)大于新生代中使用的空间(max_promotion_in_bytes),或者大于之前平均晋升的old的大小(av_promo),返回false。cms gc是每隔一个周期(默认2s)就会做一次这个检查,如果为false,则不执行YGC,而触发cms gc。

 

我们经常使用的是啥GC方式?

针对目前线上机器的情况(8G的物流内存),heap区一般设置在4g或者5g左右,一般是使用CMS GC,这时候:

young区使用ParNew(并行GC),Old+Perm(需要单独设置)使用CMS,整个堆(young+old+perm)使用MSC((Mark Sweep Compact)是CMS GC算法的Full GC算法,单线程回收整个堆,回收过程有严格的步骤。压缩,所以回收完理论上任何Generation都不会有内存碎片)压缩回收的方式。

 

读懂GC日志?

基本上都是这种格式:回收前区域占用的大小->回收后区域占用的大小(区域设置的大小),占用的时间

 

1、promotion failed的一段日志

1
2
2013 - 11 -27T03: 00 : 53.638 + 0800 35333.562 : [GC  35333.562 : [ParNew (promotion failed): 1877376K->1877376K(1877376K),  15.7989680  secs] 35349.361 : [CMS: 2144171K->2129287K(2146304K),  10.4200280  sec
s] 3514052K->2129287K(4023680K), [CMS Perm : 119979K->118652K(190132K)],  26.2193500  secs] [Times: user= 30.35  sys= 5.19 , real= 26.22  secs]

解释如下:

1
2
3
4
5
1877376K->1877376K(1877376K),  15.7989680  secs   young区
2144171K->2129287K(2146304K),  10.4200280  sec     old区情况
3514052K->2129287K(4023680K)                     heap区情况
119979K->118652K(190132K)],  26.2193500  secs      perm区情况 
[Times: user= 30.35  sys= 5.19 , real= 26.22  secs]    整个过程的时间消耗

 

2、一段正常的CMS的日志

1
2
3
4
5
6
7
8
9
10
11
12
13
14
2013 - 11 -27T04: 00 : 12.819 + 0800 38892.743 : [GC [ 1  CMS-initial-mark: 1547313K(2146304K)] 1734957K(4023680K),  0.1390860  secs] [Times: user= 0.14  sys= 0.00 , real= 0.14  secs]
2013 - 11 -27T04: 00 : 12.958 + 0800 38892.883 : [CMS-concurrent-mark-start]
2013 - 11 -27T04: 00 : 19.231 + 0800 38899.155 : [CMS-concurrent-mark:  6.255 / 6.272  secs] [Times: user= 8.49  sys= 1.57 , real= 6.27  secs]
2013 - 11 -27T04: 00 : 19.231 + 0800 38899.155 : [CMS-concurrent-preclean-start]
2013 - 11 -27T04: 00 : 19.250 + 0800 38899.175 : [CMS-concurrent-preclean:  0.018 / 0.019  secs] [Times: user= 0.02  sys= 0.00 , real= 0.02  secs]
2013 - 11 -27T04: 00 : 19.250 + 0800 38899.175 : [CMS-concurrent-abortable-preclean-start]
  CMS: abort preclean due to time  2013 - 11 -27T04: 00 : 25.252 + 0800 38905.176 : [CMS-concurrent-abortable-preclean:  5.993 / 6.002  secs] [Times: user= 6.97  sys= 2.16 , real= 6.00  secs]
2013 - 11 -27T04: 00 : 25.253 + 0800 38905.177 : [GC[YG occupancy:  573705  K ( 1877376  K)] 38905.177 : [Rescan (parallel) ,  0.3685690  secs] 38905.546 : [weak refs processing,  0.0024100  secs] 38905.548 : [cla
ss unloading,  0.0177600  secs] 38905.566 : [scrub symbol & string tables,  0.0154090  secs] [ 1  CMS-remark: 1547313K(2146304K)] 2121018K(4023680K),  0.4229380  secs] [Times: user= 1.41  sys= 0.01 , real=
0.43  secs]
2013 - 11 -27T04: 00 : 25.676 + 0800 38905.601 : [CMS-concurrent-sweep-start]
2013 - 11 -27T04: 00 : 26.436 + 0800 38906.360 : [CMS-concurrent-sweep:  0.759 / 0.760  secs] [Times: user= 1.06  sys= 0.48 , real= 0.76  secs]
2013 - 11 -27T04: 00 : 26.436 + 0800 38906.360 : [CMS-concurrent-reset-start]
2013 - 11 -27T04: 00 : 26.441 + 0800 38906.365 : [CMS-concurrent-reset:  0.005 / 0.005  secs] [Times: user= 0.00  sys= 0.00 , real= 0.00  secs]

这个是一个正常的CMS的日志,共分为七个步骤,重点关注initial-mark和remark这两个阶段,因为这两个是停机的。

A、[GC [1 CMS-initial-mark: 1547313K(2146304K)] 1734957K(4023680K), 0.1390860 secs] [Times: user=0.14 sys=0.00, real=0.14 secs]

各个数据依次表示标记前后old区的所有对象占内存大小和old的capacity,整个JavaHeap(不包括perm)所有对象占内存总的大小和JavaHeap的capacity。

B、2013-11-27T04:00:25.253+0800: 38905.177: [GC[YG occupancy: 573705 K (1877376 K)]38905.177: [Rescan (parallel) , 0.3685690 secs]38905.546: [weak refs processing, 0.0024100 secs]38905.548: [class unloading, 0.0177600 secs]38905.566: [scrub symbol & string tables, 0.0154090 secs] [1 CMS-remark: 1547313K(2146304K)] 2121018K(4023680K), 0.4229380 secs] [Times: user=1.41 sys=0.01, real=0.43 secs]

Rescan (parallel)表示的是多线程处理young区和多线程扫描old+perm的卡表的总时间, parallel 表示多GC线程并行。

weak refs processing 处理old区的弱引用的总时间,用于回收native memory。

class unloading 回收SystemDictionary消耗的总时间。

 

3、一段正常的Young GC的日志

1
2
2013 - 11 -27T04: 00 : 07.345 + 0800 38887.270 : [GC  38887.270 : [ParNew: 1791076K->170624K(1877376K),  0.2324440  secs] 2988366K->1413629K(4023680K),  0.2326470  secs] [Times: user= 0.80  sys= 0.00 , real= 0 .
23  secs]

ParNew这个表明是并行的回收方式,具体的分别是young区、整个heap区的情况;

 

4、一段通过system.gc产生的FullGC日志

1
2013 - 07 -21T17: 44 : 01.554 + 0800 50.568 : [Full GC (System)  50.568 : [CMS: 943772K->220K(2596864K),  2.3424070  secs] 1477000K->220K(4061184K), [CMS Perm : 3361K->3361K(98304K)],  2.3425410  secs] [Times: user= 2.33  sys= 0.01 , real= 2.34  secs]

解释如下:

Full GC (System)意味着这是个system.gc调用产生的MSC。

“943772K->220K(2596864K), 2.3424070 secs”表示:这次MSC前后old区内总对象大小,old的capacity及这次MSC耗时。

“1477000K->220K(4061184K)”表示:这次MSC前后JavaHeap内总对象大小,JavaHeap的capacity。

“3361K->3361K(98304K)], 2.3425410 secs”表示:这次MSC前后Perm区内总对象大小,Perm区的capacity。

 

5、一个特殊的GC日志,根据动态计算直接进行的FullGC(MSC的方式)

1
2013 - 03 -13T13: 48 : 06.349 + 0800 7.092 : [GC  7.092 : [ParNew: 471872K->471872K(471872K),  0.0000420  secs] 7.092 : [CMS: 366666K->524287K(524288K),  27.0023450  secs] 838538K->829914K(996160K), [CMS Perm : 3196K->3195K(131072K)],  27.0025170  secs]

ParNew的时间特别短,jvm在minor gc前会首先确认old是不是足够大,如果不够大,这次young gc直接返回,进行MSC。

 

参考文章:

http://kenwublog.com/docs/java6-jvm-options-chinese-edition.htm   JVM参数大全

http://tmalltesting.com/archives/663 悲观策略

http://hellojava.info/?p=142 CMS GC不建议3G的原因

毕玄的《分布式java基础》



已有 0 人发表留言,猛击->> 这里<<-参与讨论


ITeye推荐



相关 [cms gc 问题] 推荐:

一次CMS GC问题排查过程(理解原理+读懂GC日志)

- - ITeye博客
这个是之前处理过的一个线上问题,处理过程断断续续,经历了两周多的时间,中间各种尝试,总结如下. 1、问题的场景和处理过程;2、GC的一些理论东西;3、看懂GC的日志. 问题场景:线上机器在半夜会推送一个700M左右的数据,这个时候有个数据置换的过程,也就是说有700M*2的数据在heap区域中,线上系统超时比较多,导致了很严重(严重程度就不说了)的问题.

CMS gc实践总结

- - 编程语言 - ITeye博客
声明:原文转自http://www.blogjava.net/killme2008/archive/2009/09/22/295931.html,该文所有合法权益归原作者所有,仅在此做技术分享使用. 首先感谢阿宝同学的帮助,我才对这个gc算法的调整有了一定的认识,而不是停留在过去仅仅了解的阶段. 在读过sun的文档和跟阿宝讨论之后,做个小小的总结.

G1,CMS及PARALLEL GC的比较

- - Java译站
这篇文章正好接上前一年我们做的一次现实环境下不同GC算法性能比较的试验. 这次我们仍然进行同样的试验,不过增加了对G1回收器的测试,并且在多个平台进行测试. 今年我们测试的垃圾回收器有如下几个:. 我们使用现成的 JIRA任务来运行这个测试. 选择它的原因非常简单——除去Minecraft(一款著名网游),愤怒的小鸟,以及Eclipse不说, JIRA应该是最著名的Java应用程序了.

一次CMS GC的调优工作

- - 舒の随想日记
某台机器的内存比较大,之前的JVM参数是4G的堆,在压测过程中发现当QPS上来以后,Full GC会开始抬头,YoungGC的频率就不用说了,比较高. 观察GC日志和jstat -gcutil,感觉是QPS在峰值的时候对象创建比较多,也有大对象产生. 于是打算加大堆的大小来延缓GC的时机,并且有一些GC参数的优化,反复调整后找到了一个适合我们的参数(没有一个best的参数,还是得按照应用的的情况去测量,最好是一遍压测一遍调整,最终找到一个best fit的参数组).

系统频繁Full gc问题分析及解决办法

- - JavaRanger - 专注JAVA高性能程序开发、JVM、Mysql优化、算法
上周开始系统在业务高峰期一直收到Full gc报警,监控显示fgc频繁,下图是监控图,左边红框是优化前效果,右边是优化后,优化后fgc基本为0. 1.查看gc日志,发现old区fgc后大小没有变化,如下图:. 2.去线上dump内存看是什么对象,用memory analyzer分析,Retained Size竟然有2.4G,全是sun.awt.SunToolkit这个对象,其实到这一步已经可以确定是什么问题了,只是自己对系统不是很熟悉,导致定位具体的问题代码花了一些时间.

JVM 调优 —— GC 长时间停顿问题及解决方法

- - ImportNew
垃圾收集器长时间停顿,表现在 Web 页面上可能是页面响应码 500 之类的服务器错误问题,如果是个支付过程可能会导致支付失败,将造成公司的直接经济损失,程序员要尽量避免或者说减少此类情况发生. 并发模式失败(concurrent mode failure). 在 CMS 启动过程中,新生代提升速度过快,老年代收集速度赶不上新生代提升速度.

Java GC 调优

- - Darktea
关于 Java GC 已经有很多好的文档了, 比如这些:. 但是这里还是想再重点整理一下 Java GC 日志的格式, 可以作为实战时的备忘录.. 同时也会再整理一下各种概念. 一, JDK 6 提供的各种垃圾收集器. 先整理一下各种垃圾收集器.. 新生代收集器: Serial, ParNew, Parallel Scavenge (MaxGCPauseMillis vs.

[译]GC专家系列3-GC调优

- - SegmentFault 最新的文章
原文链接: http://www.cubrid.org/blog/dev-platform/how-to-tune-java-garbage-collection/. 本篇是”GC专家系列“的第三篇. 在第一篇 理解Java垃圾回收中我们学习了几种不同的GC算法的处理过程,GC的工作方式,新生代与老年代的区别.

GC 日志分析

- - 码蜂笔记
不同的JVM及其选项会输出不同的日志. 生成下面日志使用的选项: -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -Xloggc:d:/GClogs/tomcat6-gc.log. 最前面的数字 4.231 和 4.445 代表虚拟机启动以来的秒数.

初级分代GC

- - C++博客-首页原创精华区
通常情况下GC分为两种,分别是:扫描GC(Tracing GC)和引用计数GC(Reference counting GC). 其中扫描GC是比较常用的GC实现方法,其原理是:把正在使用的对象找出来,然后把未被使用的对象释放. 而引用计数GC则是对每个对象都添加一个计数器,引用增加一个计数器就加一,引用减少一个计数器就减一,当计数器减至零时,把对象回收释放.