Why CMS(concurrent mode failure) happened here?

Question

Operation System: Red Hat Linux 4.8

CPU Info: Intel(R) Xeon(R) CPU 5160  @ 3.00GHz  X 16

JDK version: "1.5.0_16" 

JVM Parameter:
-server 
-Xmx1024m 
-Xms1024m 
-XX:NewSize=256m 
-XX:MaxNewSize=256m 
-XX:PermSize=128m 
-XX:MaxPermSize=128m 
-XX:SurvivorRatio=8 
-XX:+PrintGCDetails 
-XX:+PrintGCTimeStamps 
-XX:+UseConcMarkSweepGC 
-XX:+UseCMSCompactAtFullCollection 
-XX:CMSFullGCsBeforeCompaction=5 
-XX:CMSInitiatingOccupancyFraction=60 
-XX:CMSMaxAbortablePrecleanTime=5 
-XX:+CMSPermGenSweepingEnabled 
-XX:+CMSClassUnloadingEnabled 
-XX:MaxGCPauseMillis=1500 

JVM GC Log:

945188.489: [GC 945188.489: [ParNew: 224543K->14968K(235968K), 0.0506680 secs] 552200K->344514K(1022400K), 0.0507700 secs] 

945242.102: [GC 945242.102: [ParNew: 224760K->15374K(235968K), 0.0632410 secs] 554306K->346710K(1022400K), 0.0633450 secs] 

945270.397: [GC 945270.402: [ParNew: 225163K->225163K(235968K), 0.0000230 secs]945270.402: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor70] 
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor58] 
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor38] 
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor62] 
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor54] 
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor74] 
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor53] 
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor73] 
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor64] 
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor39] 
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor59] 
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor51] 
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor42] 
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor48] 
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor76] 
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor52] 
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor57] 
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor61] 
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor56] 
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor55] 
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor63] 
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor60] 
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor40] 
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor65] 
: 331336K->71676K(786432K), 13.8120660 secs] 556499K->71676K(1022400K), 13.8122360 secs] 

945289.234: [GC 945289.234: [ParNew: 209792K->2581K(235968K), 0.0065240 secs] 281468K->74257K(1022400K), 0.0066160 secs] 

945324.703: [GC 945324.703: [ParNew: 212373K->3829K(235968K), 0.0081040 secs] 284049K->75506K(1022400K), 0.0082040 secs] 

Why CMS(concurrent mode failure) happened here?

The old generation seems : 331336K->71676K(786432K)

Answer 1

Concurrent Mode Failure as defined

The message "concurrent mode failure" signifies that the concurrent collection of the tenured generation did not finish before the tenured generation became full.

In other words, the new generation is filling up too fast, it is overflowing to tenured generation but the CMS could not clear out the tenured generation in the background.

In your case, at 945270.397

ParNew: 225163K->225163K(235968K) shows the Young was full and could not clear objects at all.

Update

A similar log to yours is explained here says

This shows that a ParNew collection was requested, but was not attempted. (The reason is that it was estimated that there was not enough space in the CMS generation to promote the worst-case surviving young generation objects.) We name this failure a "full promotion guarantee failure". As a result, the concurrent mode of CMS is interrupted and a full GC is invoked.

So as I see it, a full GC on the young objects of 225M as well as the Tenured of 331K takes 13 seconds and gets the heap down to 71 M, but this has been a result of the concurrent mode failure

Suggestion

If you are really creating so many old objects, then you probably need a bigger heap.

Or reduce try reducing the -XX:CMSInitiatingOccupancyFraction from 60 but dont think that will make much of a diff