CMS Collector Having Random Fits

Hello... we are using 1.4.2_05 JVM, Solaris 8, on a high-end
web-server application.  We are using the Concurrent Mark Sweep (CMS)
garbage collector and have been - until now - having success in tuning
the parameters.

However, since adding the extra tuning, we get random, sudden bursts
of Mark-Sweep collections, interspersed with Full GCs.... so far only
during LOW server load...  During HIGH load, the Mark-Sweeps seem
fine, and full GCs are rare.

Here is our command line thus far:

-server -Xms768M -Xmx768M -Xss256k -XX:NewSize=192m
-XX:MaxNewSize=192m -XX:+DisableExplicitGC -XX:+UseConcMarkSweepGC
-XX:+UseParNewGC -XX:+CMSParallelRemarkEnabled
-XX:CMSInitiatingOccupancyFraction=60 -verbosegc -XX:+PrintGCDetails
-XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -Ddebug=false


Here's a Mark-Sweep:

83173.121: [GC [1 CMS-initial-mark: 491664K(589824K)]
527438K(786304K), 0.0654048 secs]
83173.186: [CMS-concurrent-mark-start]
83174.344: [CMS-concurrent-mark: 1.157/1.157 secs]
83174.344: [CMS-concurrent-preclean-start]
83174.368: [CMS-concurrent-preclean: 0.024/0.025 secs]
83174.380: [GC83174.380: [Rescan (parallel) , 0.0813172
secs]83174.461: [weak refs processing, 0.0062560 secs] [1 CMS-remark:
491664K(589824K)] 538495K(786304K), 0.0879480 secs]
83174.468: [CMS-concurrent-sweep-start]
83174.954: [CMS-concurrent-sweep: 0.485/0.485 secs]
83174.954: [CMS-concurrent-reset-start]
83175.022: [CMS-concurrent-reset: 0.069/0.069 secs]

These must not be getting it done, as FULL (stop-the-world) GCs often
occur as well:

Heap
par new generation   total 196480K, used 196352K [0xc5800000,
0xd1800000, 0xd1800000)
eden space 196352K, 100% used [0xc5800000, 0xd17c0000, 0xd17c0000)
from space 128K,   0% used [0xd17c0000, 0xd17c0000, 0xd17e0000)
to   space 128K,   0% used [0xd17e0000, 0xd17e0000, 0xd1800000)
concurrent mark-sweep generation total 589824K, used 488305K
[0xd1800000, 0xf5800000, 0xf5800000)
concurrent-mark-sweep perm gen total 37696K, used 22855K [0xf5800000,
0xf7cd0000, 0xf9800000)

83222.579: [ParNew: 196352K->196352K(196480K), 0.0000502
secs]83222.579: [CMS: 488305K->492932K(589824K), 3.4133579 secs]
684657K->492932K(786304K) Heap after GC invocations=1944:

Heap
par new generation   total 196480K, used 0K [0xc5800000, 0xd1800000,
0xd1800000)
eden space 196352K,   0% used [0xc5800000, 0xc5800000, 0xd17c0000)
from space 128K,   0% used [0xd17c0000, 0xd17c0000, 0xd17e0000)
to   space 128K,   0% used [0xd17e0000, 0xd17e0000, 0xd1800000)
concurrent mark-sweep generation total 589824K, used 492932K
[0xd1800000, 0xf5800000, 0xf5800000)
concurrent-mark-sweep perm gen total 37696K, used 22855K [0xf5800000,
0xf7cd0000, 0xf9800000)
} , 3.4143169 secs]


But the Full GCs appear to be failing miserably too
(488305K->492932K)!

Eventually, after a while, everything suddenly recovers and goes back
to normal.

Based on our New and Tenured sizing (or other params), can anyone
think of why these "episodes" would occur suddenly, under LOW load,
with a healthy amount of heap available immediately prior to this?

thanks

-Chris

We experienced some similar behaviour and I would like to know, if the
solution we found is indeed solving this problem. Below you find our
setup.

I think UseCMSInitiatingOccupancyOnly was the trick, but really didn't
want to  try every combination.

Best regards,
Walter

# ---------------------------------
# Set JVM Options
# ---------------------------------
OPTIONS="-Xms256m -Xmx256m -server"

#OPTIONS="$OPTIONS -verbose:gc"
OPTIONS="$OPTIONS -Xloggc:logs/gc.log"
OPTIONS="$OPTIONS -XX:+PrintGCTimeStamps"
OPTIONS="$OPTIONS -XX:+PrintGCDetails"
OPTIONS="$OPTIONS -XX:+PrintGCApplicationStoppedTime"
#OPTIONS="$OPTIONS -XX:+PrintHeapAtGC"
#OPTIONS="$OPTIONS -XX:+PrintTenuringDistribution"

#OPTIONS="$OPTIONS -XX:+PrintCompilation"
#OPTIONS="$OPTIONS -XX:+TraceClassLoading"
#OPTIONS="$OPTIONS -XX:+TraceClassUnloading"

#OPTIONS="$OPTIONS -XX:NewRatio=2"
OPTIONS="$OPTIONS -XX:NewSize=32M"
OPTIONS="$OPTIONS -XX:MaxNewSize=32M"
OPTIONS="$OPTIONS -XX:PermSize=64M"
OPTIONS="$OPTIONS -XX:MaxPermSize=64M"

#OPTIONS="$OPTIONS -XX:TargetSurvivorRatio=50"
OPTIONS="$OPTIONS -XX:SurvivorRatio=1024"
OPTIONS="$OPTIONS -XX:MaxTenuringThreshold=0"

#OPTIONS="$OPTIONS -XX:+DisableExplicitGC"
OPTIONS="$OPTIONS -XX:+UseParNewGC"
OPTIONS="$OPTIONS -XX:+UseConcMarkSweepGC"
OPTIONS="$OPTIONS -XX:+CMSParallelRemarkEnabled"
OPTIONS="$OPTIONS -XX:+CMSPermGenSweepingEnabled"
OPTIONS="$OPTIONS -XX:+CMSClassUnloadingEnabled"
OPTIONS="$OPTIONS -XX:+UseCMSCompactAtFullCollection"
OPTIONS="$OPTIONS -XX:CMSFullGCsBeforeCompaction=0"
OPTIONS="$OPTIONS -XX:CMSInitiatingOccupancyFraction=60"
OPTIONS="$OPTIONS -XX:+UseCMSInitiatingOccupancyOnly"

OPTIONS="$OPTIONS -XX:-UseTLAB"
#OPTIONS="$OPTIONS -XX:SoftRefLRUPolicyMSPerMB=1000"

PROPERTIES="$PROPERTIES -Dsun.rmi.dgc.server.gcInterval=3600000"
PROPERTIES="$PROPERTIES -Dsun.rmi.dgc.client.gcInterval=3600000"

We experienced some similar behaviour and I would like to know, if the
solution we found is indeed solving this problem. Below you find our
setup.

I think UseCMSInitiatingOccupancyOnly was the trick, but really didn't
want to  try every combination.

Best regards,
Walter

# ---------------------------------
# Set JVM Options
# ---------------------------------
OPTIONS="-Xms256m -Xmx256m -server"

#OPTIONS="$OPTIONS -verbose:gc"
OPTIONS="$OPTIONS -Xloggc:logs/gc.log"
OPTIONS="$OPTIONS -XX:+PrintGCTimeStamps"
OPTIONS="$OPTIONS -XX:+PrintGCDetails"
OPTIONS="$OPTIONS -XX:+PrintGCApplicationStoppedTime"
#OPTIONS="$OPTIONS -XX:+PrintHeapAtGC"
#OPTIONS="$OPTIONS -XX:+PrintTenuringDistribution"

#OPTIONS="$OPTIONS -XX:+PrintCompilation"
#OPTIONS="$OPTIONS -XX:+TraceClassLoading"
#OPTIONS="$OPTIONS -XX:+TraceClassUnloading"

#OPTIONS="$OPTIONS -XX:NewRatio=2"
OPTIONS="$OPTIONS -XX:NewSize=32M"
OPTIONS="$OPTIONS -XX:MaxNewSize=32M"
OPTIONS="$OPTIONS -XX:PermSize=64M"
OPTIONS="$OPTIONS -XX:MaxPermSize=64M"

#OPTIONS="$OPTIONS -XX:TargetSurvivorRatio=50"
OPTIONS="$OPTIONS -XX:SurvivorRatio=1024"
OPTIONS="$OPTIONS -XX:MaxTenuringThreshold=0"

#OPTIONS="$OPTIONS -XX:+DisableExplicitGC"
OPTIONS="$OPTIONS -XX:+UseParNewGC"
OPTIONS="$OPTIONS -XX:+UseConcMarkSweepGC"
OPTIONS="$OPTIONS -XX:+CMSParallelRemarkEnabled"
OPTIONS="$OPTIONS -XX:+CMSPermGenSweepingEnabled"
OPTIONS="$OPTIONS -XX:+CMSClassUnloadingEnabled"
OPTIONS="$OPTIONS -XX:+UseCMSCompactAtFullCollection"
OPTIONS="$OPTIONS -XX:CMSFullGCsBeforeCompaction=0"
OPTIONS="$OPTIONS -XX:CMSInitiatingOccupancyFraction=60"
OPTIONS="$OPTIONS -XX:+UseCMSInitiatingOccupancyOnly"

OPTIONS="$OPTIONS -XX:-UseTLAB"
#OPTIONS="$OPTIONS -XX:SoftRefLRUPolicyMSPerMB=1000"

PROPERTIES="$PROPERTIES -Dsun.rmi.dgc.server.gcInterval=3600000"
PROPERTIES="$PROPERTIES -Dsun.rmi.dgc.client.gcInterval=3600000"