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

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

[kristoffer]

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

[Jon Masamitsu]

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

[Clemens Eisserer]

If nothing helps, you can still disable -XX:+DisableExplicitGC and
call System.gc() when there isn't any time-critical load, maybe once a
day.
G1 could be a big win in this situation.

- Clemens

2009/6/3 kristoffer <kristoffer.sjogren@...>:

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