5
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)

Aleš
  • 8,896
  • 8
  • 62
  • 107
user447044
  • 51
  • 1
  • 1
  • 2

1 Answers1

10

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

Bill the Lizard
  • 398,270
  • 210
  • 566
  • 880
JoseK
  • 31,141
  • 14
  • 104
  • 131
  • Thank you for your answer. My Tenured have allocated 786432k(768m) memory. Where do you see 'the Old went form 330Mb to 716Mb'? – user447044 Sep 14 '10 at 07:48
  • Ah i've incorrectly counted the 71676K as 716 M, it is in fact 71 M. – JoseK Sep 14 '10 at 08:05
  • 331336K->71676K(786432K),It means before gc,Tenured have used 331336k,after gc,Tenured have used 71676k.And my Tenured have allocated 786432k. So the question came,331336/786432=42% of tenured was used,but why CMS(concurrent mode failure) happened here ? – user447044 Sep 14 '10 at 08:22
  • @user447044: see the block in my update. Though only 42% of tenured was used, *the JVM estimated that promotion would fail and interrupted the CMS* – JoseK Sep 14 '10 at 08:29
  • 1
    As the article said,i think problem might happened because of 'fragmentation problem',though it wasn't happened frequently in JDK 1.5. I change these parameter: -XX:CMSFullGCsBeforeCompaction=5 to 1, -XX:CMSInitiatingOccupancyFraction=60 to 50, -XX:SurvivorRatio=8 to 6, Add: -XX:+UseCMSInitiatingOccupancyOnly=true . I will monitor the log. – user447044 Sep 14 '10 at 09:51
  • I have another question,On my server,i have 16 processors . Is Parallel Scavenge GC better than CMS GC ? – user447044 Sep 14 '10 at 10:35
  • @user447044: Well you need to try that out. – JoseK Sep 14 '10 at 10:50