Concurrent mode failure... fragmentation?

[Kristoffer Sjögren]

Hi Jon,

Thanks for the suggestion, i will try it out during the weekend and see if it helps.

However, spontanously it feels as if this measure only will delay fragmentation since less memory will be shuffled around in oldgen, or? 

-Kristoffer


-----Original Message-----
From: Jon.Masamitsu at Sun.COM [mailto:Jon.Masamitsu at Sun.COM] 
Sent: den 4 juni 2009 00:32
To: Kristoffer Sjögren
Cc: hotspot-gc-dev at openjdk.java.net
Subject: Re: Concurrent mode failure... fragmentation?

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.ORBSinglet
> on -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 
> 1627282K->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 
> 1643023K->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.pn
> g 
> 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
>