系统最常用的CMS GC mode——ParNew & CMS（Serial Old作为替补）（heap> 5g）

工作中 常用的 CMS  GC模式  

refer to http://iamzhongyong.iteye.com/blog/1989829

如何读懂GC日志：

https://blogs.oracle.com/poonam/entry/understanding_cms_gc_logs

注： CMS GC下 会在特殊情况（jvm认为内存不够了concurrent mode failure,promotion fail） 转而停下所有线程 去做full gc，也就是MSC(单线程)就是Serial Old（也算一次full gc）作为替补，慢   参考 http://www.cnblogs.com/zuoxiaolong/p/jvm8.html

另外如果算一次 full gc ，实践中 一次 CMS 中有两次 stop the world 就算两次 full gc了， 而MSC Serial Old作为替补也算full gc， my god!  http://www.tuicool.com/articles/jq2yIza

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

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的（7phase  参考文章顶），其他步骤均和应用并行进行。持久代的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。

（CMS 中full gc采用的MSC 是单线程的，所以特别慢，这里有27s）

 

参考文章：

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基础》

如何读懂GC日志：

https://blogs.oracle.com/poonam/entry/understanding_cms_gc_logs

——————————

——————————————————————

实例

为什么CMS GC时出现Concurrent Mode Failure？

    并发收集器（concurrentcollector）指的是回收年老代和持久代时，采用多个线程和应用线程并发执行，减少应用停顿时间，但如果参数设置不当，容易出现Concurrent ModeFailure现象，此时JVM将采用停顿的方式进行full gc（就是parallel old 作为替补，算full gc此时，cms 因为7个阶段中有两次停顿算两次），整个gc时间相当可观，完全违背了采用CMS GC的初衷。

    出现此现象的原因主要有两个：一个是在年老代被用完之前不能完成对无引用对象的回收；一个是当新空间分配请求在年老代的剩余空间中得到满足。原文如（if theconcurrent collector is unable to finish reclaiming the unreachable objectsbefore the tenured generation fills up, or if an allocation cannot be satisfiedwith the available free space blocks in the tenured generation, then theapplication is paused and the collection is completed with all the applicationthreads stopped）。

出现此现象的具体gc日志如下：

90003.167: [GC 90003.167: [ParNew: 261760K->0K(261952K), 0.0204310secs] 778897K->520196K(1310528K), 0.0207190 secs]
90006.049: [GC 90006.050: [ParNew: 261760K->0K(261952K), 0.0136380 secs]781956K->521446K(1310528K), 0.0138720 secs]
90010.628: [GC 90010.628: [ParNew: 261760K->261760K(261952K), 0.0000350secs]90010.628: [CMS (concurrent mode failure)[Unloadingclass sun.reflect.GeneratedSerializationConstructorAccessor1818]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor1816]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor1819]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor1821]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor1817]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor1822]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor1820]
: 521446K->415777K(1048576K), 2.2550270 secs] 783206K->415777K(1310528K),2.2553820 secs]
90015.099: [GC 90015.099: [ParNew: 261760K->0K(261952K), 0.0198180 secs]677537K->418003K(1310528K), 0.0200650 secs]
90018.670: [GC 90018.670: [ParNew: 261760K->0K(261952K), 0.0131610 secs]679763K->419115K(1310528K), 0.0133750 secs]
90022.254: [GC 90022.254: [ParNew: 261760K->0K(261952K), 0.0151240 secs]680875K->420505K(1310528K), 0.0154180 secs]

当时的JVM参数如下：

-server -Xms1280m -Xmx1280m -Xmn256m -Xss256k -XX:PermSize=128m-XX:MaxPermSize=128m -XX:+UseConcMarkSweepGC -XX:+UseParNewGC-XX:CMSFullGCsBeforeCompaction=5 -XX:+UseCMSCompactAtFullCollection  -XX:+UseCMSInitiatingOccupancyOnly -XX:+CMSClassUnloadingEnabled-XX:+DisableExplicitGC -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps

因为配置了+CMSClassUnloadingEnabled参数，所以出现Unloading classsun.reflect.GeneratedSerializationConstructorAccessor的日志，这是个好习惯，如果空间不够时可以卸载类来释放空间，以进行FULL GC，相反，如果gc日志中出现了此日志，应该检查各代的大小设置是否合理。这里应用从启动到上述现象出现时还没有进行过CMS GC，出现concurrent modefailure现象的原因是年轻代GC（ParNew），年老代所剩下的空间不足以满足年轻代，也就是开头提到的原因二。要避免此现象，方法一是降低触发CMS的阀值，即参数-XX:CMSInitiatingOccupancyFraction的值，默认值是68，所以这里调低到50，让CMS GC尽早执行，以保证有足够的空间，如下：

-server -Xms1280m -Xmx1280m -Xmn256m -Xss256k -XX:PermSize=128m-XX:MaxPermSize=128m -XX:+UseConcMarkSweepGC -XX:+UseParNewGC-XX:CMSFullGCsBeforeCompaction=1 -XX:+UseCMSCompactAtFullCollection -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSInitiatingOccupancyFraction=50-XX:+CMSClassUnloadingEnabled -XX:+DisableExplicitGC -verbose:gc-XX:+PrintGCDetails -XX:+PrintGCTimeStamps

调完之后发现还是一样的现象（这里有点不是很明白，年老代空间为1024m（1280m-256m），50%时触发CMS GC，也就是在年老代512m的时候，剩下的堆空间有512m，就算年轻代全部装进去应该也是够的）,所以怀疑是年轻代太大，有大的对象，在年老代有碎片的情况下将很难分配，所以有了第二个解决办法，即减少年轻代大小，避免放入年老代时需要分配大的空间，同时调整full gc时压缩碎片的频次，减少持久代大小，以及将触发CMS GC的阀值适当增大（因为年轻代小了，这个调大点没关系，后面可以再调试这个参数），参数如下：

-server -Xms1280m -Xmx1280m -Xmn128m -Xss256k -XX:PermSize=96m -XX:MaxPermSize=96m -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:CMSFullGCsBeforeCompaction=1 -XX:+UseCMSCompactAtFullCollection -XX:+CMSParallelRemarkEnabled -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSInitiatingOccupancyFraction=70 -XX:+CMSClassUnloadingEnabled -XX:+DisableExplicitGC -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps

调整完后没有那个现象了，这里主要起作用的就是调小年轻代大小。在年老代到达826m(触发CMS阀值(1280-128)*0.7=806m)时出现了CMS GC，用时27ms，日志如下：

705.444: [GC 705.445: [ParNew: 130944K->0K(131008K), 0.0197680 secs]954628K->826284K(1310656K), 0.0199720 secs]

705.467:[GC [1 CMS-initial-mark: 826284K(1179648K)] 826744K(1310656K), 0.0271540 secs]

705.494:[CMS-concurrent-mark-start]

706.717:[CMS-concurrent-mark: 1.223/1.223 secs]

706.717:[CMS-concurrent-preclean-start]

706.717:[CMS-concurrent-preclean: 0.000/0.000 secs]

706.742:[CMS-concurrent-abortable-preclean-start]

706.742:[CMS-concurrent-abortable-preclean: 0.000/0.000 secs]
707.067: [GC 707.067: [ParNew: 130944K->0K(131008K), 0.0160200 secs]957228K->827348K(1310656K), 0.0162110 secs]
707.796: [GC[YG occupancy: 66671 K (131008 K)]707.796: [Rescan (parallel) ,0.0278280 secs]707.824: [weak refs processing, 0.0420770 secs] [1 CMS-remark:827348K(1179648K)] 894019K(1310656K), 0.0711970 secs]
707.877: [CMS-concurrent-sweep-start]
708.453: [GC 708.454: [ParNew: 130944K->0K(131008K), 0.0203760 secs]848439K->718796K(1310656K), 0.0205780 secs]
709.833: [GC 709.833: [ParNew: 130944K->0K(131008K), 0.0160170 secs]430484K->301411K(1310656K), 0.0161840 secs]
709.916: [CMS-concurrent-sweep: 1.974/2.040 secs]
709.916: [CMS-concurrent-reset-start]
709.951: [CMS-concurrent-reset: 0.034/0.034 secs]
711.187: [GC 711.187: [ParNew: 130944K->0K(131008K), 0.0130890 secs]413136K->283326K(1310656K), 0.0132600 secs]

观察一段时间的gc情况，gc效率也很高，单次YGCT<20ms，FGCT <40ms：

$ jstat -gcutil 31935 1000
  S0     S1     E      O     P     YGC     YGCT    FGC    FGCT    GCT

  0.00   0.00  64.29  36.47  73.15   1293  19.514     6    0.211   19.725
  0.00   0.00  64.33  36.47  73.15   1293  19.514     6    0.211   19.725
  0.00   0.00  64.41  36.47  73.15   1293  19.514     6    0.211   19.725
  0.00   0.00  64.45  36.47  73.15   1293  19.514     6    0.211   19.725
  0.00   0.00  64.49  36.47  73.15   1293  19.514     6    0.211   19.725
  0.00   0.00  64.58  36.47  73.15   1293  19.514     6    0.211   19.725
  0.00   0.00  64.63  36.47  73.15   1293  19.514     6    0.211   19.725
  0.00   0.00  64.69  36.47  73.15   1293  19.514     6    0.211   19.725
  0.00   0.00  64.72  36.47  73.15   1293  19.514     6    0.211   19.725
  0.00   0.00  64.75  36.47  73.15   1293  19.514     6    0.211   19.725
  0.00   0.00  64.79  36.47  73.15   1293  19.514     6    0.211   19.725
  0.00   0.00  64.84  36.47  73.15   1293  19.514     6    0.211   19.725
  0.00   0.00  64.90  36.47  73.15   1293  19.514     6    0.211   19.725
  0.00   0.00  64.95  36.47  73.15   1293  19.514     6    0.211   19.725
  0.00   0.00  64.99  36.47  73.15   1293  19.514     6    0.211   19.725

这时，想再测试下-XX:CMSInitiatingOccupancyFraction的值，调到80时又出现了上述现象Concurrent ModeFailure，启动后还没进行过CMS GC，在年老代914m时就出现了：

759.994: [GC 759.994: [ParNew: 130944K->0K(131008K), 0.0172910 secs]1040896K->911480K(1310656K), 0.0174730 secs]
760.879: [GC 760.879: [ParNew: 130944K->0K(131008K), 0.0300920 secs]1042424K->914190K(1310656K), 0.0302950 secs]
761.768: [GC 761.769: [ParNew: 130944K->130944K(131008K), 0.0000340secs]761.769: [CMS (concurrent mode failure)[Unloading classsun.reflect.GeneratedMethodAccessor342]edMethodAccessor348]
[Unloading class sun.reflect.GeneratedMethodAccessor411]
[Unloading class sun.reflect.GeneratedMethodAccessor407]
[Unloading class sun.reflect.GeneratedMethodAccessor541]

最后总结下，出现Concurrent ModeFailure现象时，解决办法就是要让年老代留有足够的空间，以保证新对象空间的分配。另外在JVM  BUG中有提到，JDK1.5_09版本之前，JVM参数-XX:CMSInitiatingOccupancyFraction是无效的，我这里应用环境的版本是JDK1.5_08，从gc日志来看是可以生效的。

GC时还有一个常见的错误PromotionFailed，解决办法类似，也是调整年轻代和年老代的比例，还有CMSGC的时机。