Concurrent mode failure... fragmentation?

Thu Jun 4 14:55:20 UTC 2009

Kristoffer Sjögren wrote On 06/04/09 02:23,:

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

Yes, it is sometimes the case that the inevitable is only delayed but
allowing more objects to die in the young gen has two benefits.

0) Objects that a contributing to the fragmentation may die in the
young gen and not have a chance to fragment the old gen.

1) The old gen is filling more slowly so there is more time for
objects that may be contributing to the fragmentation to die
and be collected (reducing the fragmentation).

Good luck.  And if this helps, you might be able to use
a larger value for CMSInitiatingOccupancyFraction.
If the old gen is filling more slowly, maybe you don't have
to have CMS running constantly.

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