Concurrent mode failure... fragmentation?

[Jon Masamitsu]

Kristoffer,

Yes, it is difficult to determine if fragmentation
is the problem.  Try using the young gen to filter
out more of the objects before they get promoted
to the old gen.

-XX:SurvivorRatio=8
-XX:MaxTenuringThreshold=15

Unless you have a specific need to have a small
young gen to keep the minor collection pauses
down, I'd also suggest

-Xmn512m or -Xmn1g

Jon

On 06/ 3/09 01:24 AM, kristoffer wrote:
> 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 
>