atom feed5 messages in net.java.openjdk.hotspot-gc-devRE: Concurrent mode failure... fragme...
FromSent OnAttachments
kristofferJun 3, 2009 1:24 am 
Jon MasamitsuJun 3, 2009 3:31 pm 
Kristoffer SjögrenJun 4, 2009 2:23 am 
Jon MasamitsuJun 4, 2009 7:54 am 
Clemens EissererJun 4, 2009 9:13 am 
Subject:RE: Concurrent mode failure... fragmentation?
From:Kristoffer Sjögren (kris@ericsson.com)
Date:Jun 4, 2009 2:23:25 am
List:net.java.openjdk.hotspot-gc-dev

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.@Sun.COM [mailto:Jon.@Sun.COM] Sent: den 4 juni 2009 00:32 To: Kristoffer Sjögren Cc: hots@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

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