Concurrent mode failure... fragmentation?

[kristoffer]

Hi

I have a tricky problem with the CMS: "concurrent mode failure" occurs every
now and then which causes a STW pause for roughly 7-8 seconds. It seems that
this is a case of fragmentation, since it occurs way before the heap is
full. I tried playing around with UseCMSCompactAtFullCollection, 
CMSInitiatingOccupancyFraction and different Xmx/Xms settings but nothing
seems to fix the problem.

Im running out of ideas... im not sure if fragmentation is the problem - is
there any way to force compaction at an earlier stage? 

I have attached the gc.log and some other statistics that can be useful.

Cheers,
-Kristoffer

Running SLES 10 SP1, JDK 1.6.06, Glassfish 2.1

-Dcom.sun.corba.ee.transport.ORBWaitForResponseTimeout=60000
-Dorg.omg.CORBA.ORBClass=com.sun.corba.ee.impl.orb.ORBImpl
-Dorg.omg.CORBA.ORBSingletonClass=com.sun.corba.ee.impl.orb.ORBSingleton
-Dsun.rmi.dgc.client.gcInterval=3600000
-Dsun.rmi.dgc.server.gcInterval=3600000
-server
-XX:+UnlockDiagnosticVMOptions
-XX:CMSFullGCsBeforeCompaction=0
-XX:+UseCMSCompactAtFullCollection
-Xmn200m
-Xmx3600m
-Xms3600m
-XX:+DisableExplicitGC
-XX:SurvivorRatio=20000
-XX:MaxTenuringThreshold=0
-XX:LargePageSizeInBytes=2m
-XX:+UseParNewGC
-XX:ParallelGCThreads=8
-XX:+UseConcMarkSweepGC
-XX:+UseCMSInitiatingOccupancyOnly
-XX:CMSInitiatingOccupancyFraction=5
-XX:+CMSParallelRemarkEnabled
-XX:+CMSConcurrentMTEnabled
-XX:ParallelCMSThreads=4
-XX:MaxPermSize=512m
-XX:PermSize=512m
-XX:+CMSClassUnloadingEnabled
-verbose:gc
-XX:+PrintGCApplicationStoppedTime
-XX:+PrintGCTimeStamps
-XX:+PrintGCDetails
-XX:+PrintHeapAtGC
-XX:+LogVMOutput
-XX:+UnlockDiagnosticVMOptions


gc.log:

123592.046: [GC 123592.046: [ParNew: 204672K->0K(204736K), 0.0484480 secs]
1627282K->1438351K(3686336K), 0.0490060 secs] [Times: user=0.24 sys=0.03,
real=0.05 secs] 
Heap after GC invocations=96778 (full 27780):
 par new generation   total 204736K, used 0K [0x00002aaaae260000,
0x00002aaabaa60000, 0x00002aaabaa60000)
  eden space 204672K,   0% used [0x00002aaaae260000, 0x00002aaaae260000,
0x00002aaabaa40000)
  from space 64K,   0% used [0x00002aaabaa40000, 0x00002aaabaa40000,
0x00002aaabaa50000)
  to   space 64K,   0% used [0x00002aaabaa50000, 0x00002aaabaa50000,
0x00002aaabaa60000)
 concurrent mark-sweep generation total 3481600K, used 1438351K
[0x00002aaabaa60000, 0x00002aab8f260000, 0x00002aab8f260000)
 concurrent-mark-sweep perm gen total 524288K, used 182144K
[0x00002aab8f260000, 0x00002aabaf260000, 0x00002aabaf260000)
}
Total time for which application threads were stopped: 0.0616680 seconds
123592.342: [CMS-concurrent-mark: 1.749/1.967 secs] [Times: user=12.46
sys=0.74, real=1.97 secs] 
123592.342: [CMS-concurrent-preclean-start]
{Heap before GC invocations=96778 (full 27780):
 par new generation   total 204736K, used 204672K [0x00002aaaae260000,
0x00002aaabaa60000, 0x00002aaabaa60000)
  eden space 204672K, 100% used [0x00002aaaae260000, 0x00002aaabaa40000,
0x00002aaabaa40000)
  from space 64K,   0% used [0x00002aaabaa40000, 0x00002aaabaa40000,
0x00002aaabaa50000)
  to   space 64K,   0% used [0x00002aaabaa50000, 0x00002aaabaa50000,
0x00002aaabaa60000)
 concurrent mark-sweep generation total 3481600K, used 1438351K
[0x00002aaabaa60000, 0x00002aab8f260000, 0x00002aab8f260000)
 concurrent-mark-sweep perm gen total 524288K, used 182144K
[0x00002aab8f260000, 0x00002aabaf260000, 0x00002aabaf260000)
123592.382: [GC 123592.383: [ParNew (promotion failed):
204672K->204672K(204736K), 0.1170700 secs]123592.500: [CMS123592.813:
[CMS-concurrent-preclean: 0.303/0.471 secs] [Times: user=0.73 sys=0.02,
real=0.47 secs] 
 (concurrent mode failure): 1445845K->1299108K(3481600K), 8.1608190 secs]
1643023K->1299108K(3686336K), 8.2785780 secs] [Times: user=8.37 sys=0.05,
real=8.28 secs] 
Heap after GC invocations=96779 (full 27780):
 par new generation   total 204736K, used 0K [0x00002aaaae260000,
0x00002aaabaa60000, 0x00002aaabaa60000)
  eden space 204672K,   0% used [0x00002aaaae260000, 0x00002aaaae260000,
0x00002aaabaa40000)
  from space 64K,   0% used [0x00002aaabaa50000, 0x00002aaabaa50000,
0x00002aaabaa60000)
  to   space 64K,   0% used [0x00002aaabaa40000, 0x00002aaabaa40000,
0x00002aaabaa50000)
 concurrent mark-sweep generation total 3481600K, used 1299108K
[0x00002aaabaa60000, 0x00002aab8f260000, 0x00002aab8f260000)
 concurrent-mark-sweep perm gen total 524288K, used 182141K
[0x00002aab8f260000, 0x00002aabaf260000, 0x00002aabaf260000)
}
Total time for which application threads were stopped: 8.2904010 seconds


http://www.nabble.com/file/p23847470/deviap112_iap_logs_gc_timeline.png 
http://www.nabble.com/file/p23847470/deviap112_iap_logs_old_heap_size.png 
http://www.nabble.com/file/p23847470/deviap112_iap_logs_gc_stats.png 

-- 
View this message in context: http://www.nabble.com/Concurrent-mode-failure...-fragmentation--tp23847470p23847470.html
Sent from the OpenJDK Hotspot Garbage Collection mailing list archive at Nabble.com.