CMS collector ignoring -XX:CMSInitiatingOccupancyFraction completely
I have a Java service that appears to ignore the
XX:CMSInitiatingOccupancyFraction flag completely. Here're the GC
related settings:
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:+PrintTenuringDistribution
-XX:+UseConcMarkSweepGC
-XX:+CMSIncrementalMode
-XX:CMSInitiatingOccupancyFraction=50
-XX:+UseCMSInitiatingOccupancyOnly
-Xmx2048m -Xms2048m
-XX:NewSize=100m
-XX:MaxNewSize=100m
Despite setting CMSInitiatingOccupancyFraction to 50% and setting
UseCMSInitiatingOccupancyOnly to true, the CMS collector continues to
wait until the tenured generation grows *way* above 50% before it
kicks in.
The reason for 50% threshold is this app being very sensitive to
pauses and I want to avoid pause if at all possible, at the expense of
memory and CPU. However because CMS doesn't start early as it should
(should start at 50% tenured occupancy), I occasionally get YG
promotions failures and results a STW collection pause, probably due
to fragmentation.
This is JRE1.6.0 on Linux. What's going on?
[1143 byte] By [
MMMMMMMa] at [2007-11-26 20:09:38]
# 1
Forget to add the GC debug outputs containing the concurrency failure, and the fact that the -XX:CMSInitiatingOccupancyFraction NOT being followed by VM:
...
1770214K->1687169K(2086912K) icms_dc=0 , 0.0537310 secs]
71999.835: [GC 71999.835: [ParNew
Desired survivor size 5242880 bytes, new threshold 4 (max 4)
- age1:1658368 bytes,1658368 total
- age2:1026032 bytes,2684400 total
- age3:868800 bytes,3553200 total
- age4:963456 bytes,4516656 total
: 86651K->6051K(92160K), 0.0501690 secs] 1769089K->1688991K(2086912K) icms_dc=0 , 0.0503720 secs]
72003.014: [GC 72003.014: [ParNew
Desired survivor size 5242880 bytes, new threshold 3 (max 4)
- age1:4058392 bytes,4058392 total
- age2:778528 bytes,4836920 total
- age3:711600 bytes,5548520 total
- age4:862768 bytes,6411288 total
: 86853K->9102K(92160K), 0.0478230 secs] 1769793K->1692981K(2086912K) icms_dc=0 , 0.0480370 secs]
72003.848: [GC 72003.848: [ParNew
Desired survivor size 5242880 bytes, new threshold 1 (max 4)
- age1:8703448 bytes,8703448 total
- age2:1095912 bytes,9799360 total
- age3:685760 bytes,10485120 total
: 91022K->10240K(92160K), 0.1913850 secs] 1774901K->1705353K(2086912K) icms_dc=3 , 0.1916010 secs]
72005.663: [GC [1 CMS-initial-mark: 1695113K(1994752K)] 1745092K(2086912K), 0.1172090 secs]
72005.781: [CMS-concurrent-mark-start]
72007.715: [GC 72007.716: [ParNew (promotion failed)
Desired survivor size 5242880 bytes, new threshold 4 (max 4)
- age1:1496680 bytes,1496680 total
: 92160K->92160K(92160K), 4.6021590 secs]72012.318: [CMS72015.057: [CMS-concurrent-mark: 2.739/9.276 secs]
(concurrent mode failure)[Unloading class sun.reflect.GeneratedConstructorAccessor6]
[Unloading class sun.reflect.GeneratedMethodAccessor2]
[Unloading class sun.reflect.GeneratedConstructorAccessor7]
[Unloading class sun.reflect.GeneratedConstructorAccessor5]
[Unloading class sun.reflect.GeneratedConstructorAccessor4]
[Unloading class sun.reflect.GeneratedConstructorAccessor8]
: 1695493K->724226K(1994752K), 10.3901920 secs] 1787273K->724226K(2086912K) icms_dc=3 , 14.9926090 secs]
72022.967: [GC [1 CMS-initial-mark: 724226K(1994752K)] 764399K(2086912K), 0.0931440 secs]
72023.061: [CMS-concurrent-mark-start]
72023.342: [GC 72023.342: [ParNew
Desired survivor size 5242880 bytes, new threshold 4 (max 4)
- age1:4330936 bytes,4330936 total
: 81920K->4931K(92160K), 0.1163110 secs] 806146K->729157K(2086912K) icms_dc=3 , 0.1165250 secs]
72024.282: [GC 72024.282: [ParNew
Desired survivor size 5242880 bytes, new threshold 4 (max 4)
- age1:3136312 bytes,3136312 total
- age2:1477392 bytes,4613704 total
: 86851K->5646K(92160K), 0.0724230 secs] 811077K->729873K(2086912K) icms_dc=3 , 0.0726500 secs]
72025.455: [GC 72025.455: [ParNew
Desired survivor size 5242880 bytes, new threshold 4 (max 4)
- age1:2179552 bytes,2179552 total
- age2:1114864 bytes,3294416 total
- age3:1359000 bytes,4653416 total
: 87566K->6060K(92160K), 0.0349260 secs] 811793K->730286K(2086912K) icms_dc=3 , 0.0351470 secs]
# 2
> I have a Java service that appears to ignore the
> XX:CMSInitiatingOccupancyFraction flag completely.
> Here're the GC
> elated settings:
>
> -XX:+PrintGCDetails
> -XX:+PrintGCTimeStamps
> -XX:+PrintTenuringDistribution
> -XX:+UseConcMarkSweepGC
> -XX:+CMSIncrementalMode
> ...
You are using 'incremental CMS' (i-cms) which is enabled by the option -XX:+CMSIncrementalMode. i-cms does not consult the CMSInitiatingOccupancyFraction flag by design; it attempts to start the collection much earlier and spread it out over a longer period.
There are some basic recommendations for tuning the incremental CMS to avoid
the full GCs you are seeing in the GC tuning guide; see
http://java.sun.com/javase/technologies/hotspot/gc/gc_tuning_6.html#icms
(That is the Java SE 6 version but the i-cms section also applies to Java SE 5.0.)
Hopefully those will help.
Note that CMS (and i-cms) can be fooled by an application that changes behavior rapidly; in particular, the metrics used to control garbage collection may not react quickly enough to large increases in the allocation rate. The command-line option CMSIncrementalSafetyFactor may help if that is the case.
jxca at 2007-7-9 23:12:47 >
