CMS GC tuning under JVM 5.0

[Jones, Doug H]

Hi,

We have considerable experience with JVM tuning of our SunOne
appservers, utilizing CMS GC and adjusting NewSize/heapsize values etc
under JVM version 1.4.2 to get some very low GC pause times.

We are currently moving to manage an application running under JVM 5.0.
This is still in Test, but our initial GC monitoring is raising some
questions.

The application has some normal activity but hourly it needs to do some
significant background processing. This drives memory use much higher
than normal. So what we see is ParNew's going from approximately one
every 5 minutes to just a second or two apart. That is of course no
problem in itself. But what we are also see is an occasional
concurrent-mode failure, followed by a relatively long single-thread STW
collection. While we haven't exactly done the correlation we're assuming
that the hourly burst in activity has coincided with the tenured area
being close to full (so the CMS GC has not been able to complete before
free space available has become less than NewSize). The two examples
below are exactly 19 hours apart.

Example 1:

31123.434: [GC 31123.434: [ParNew: 24448K->0K(24512K), 0.0294222 secs]
292487K->269028K(327616K), 0.0296926 secs]
31468.449: [GC 31468.449: [ParNew: 24448K->0K(24512K), 0.0228006 secs]
293476K->269851K(327616K), 0.0230994 secs]
31678.918: [GC 31678.919: [ParNew: 24447K->0K(24512K), 0.0950828 secs]
294299K->278163K(327616K), 0.0954078 secs]
31679.235: [GC 31679.235: [ParNew: 24391K->0K(24512K), 0.2853518 secs]
302554K->298349K(327616K), 0.2856694 secs]
31679.536: [GC [1 CMS-initial-mark: 298349K(303104K)] 298442K(327616K),
0.0033056 secs]
31679.540: [CMS-concurrent-mark-start]
31680.017: [CMS-concurrent-mark: 0.477/0.477 secs]
31680.017: [CMS-concurrent-preclean-start]
31680.023: [CMS-concurrent-preclean: 0.006/0.006 secs]
31680.023: [CMS-concurrent-abortable-preclean-start]
31768.429: [GC 31768.429: [ParNew: 24448K->24448K(24512K), 0.0000510
secs]31768.430: [CMS31768.430: [CMS-concurrent-abortable-preclean:
5.410/88.406 secs]
 (concurrent mode failure): 298349K->35861K(303104K), 0.9340408 secs]
322797K->35861K(327616K), 0.9345904 secs]


Example 2:

100064.686: [GC 100064.686: [ParNew: 24448K->0K(24512K), 0.0155892 secs]
293020K->268870K(327616K), 0.0160228 secs]
100079.843: [GC 100079.843: [ParNew: 24382K->0K(24512K), 0.0390096 secs]
293253K->291786K(327616K), 0.0393622 secs]
100079.883: [GC [1 CMS-initial-mark: 291786K(303104K)] 291881K(327616K),
0.0028736 secs]
100079.887: [CMS-concurrent-mark-start]
100080.381: [CMS-concurrent-mark: 0.494/0.494 secs]
100080.381: [CMS-concurrent-preclean-start]
100080.390: [CMS-concurrent-preclean: 0.009/0.009 secs]
100080.390: [CMS-concurrent-abortable-preclean-start]
100259.694: [GC 100259.694: [ParNew: 24448K->24448K(24512K), 0.0000456
secs]100259.694: [CMS100259.695: [CMS-concurrent-abortable-preclean:
10.649/179.305 sec
s]
 (concurrent mode failure): 291786K->43120K(303104K), 1.0073652 secs]
316234K->43120K(327616K), 1.0078356 secs]

This is not a  problem to us in Test, but if we extrapolate to
Production with a proposed heap size of 1.5GB, this may become more of
an issue.

Under JVM 1.4.2 we can circumvent the default Collector behaviour by
adding the flag "-XX:+UseCMSInitiatingOccupancyOnly=true" to ensure CMS
GC's occur at approximately the CMSInitiatingOccupancyFraction percent
full. But this flag does not appear to be available under JVM 5.0.

So we have two questions:

1) Is there an equivalent option for JVM 5.0 which will force CMS
Collections to occur with a reasonably large amount of free space left
in tenured (ie relative to NewSize), and
 
2) Could you interpret the pair of times on the
CMS-concurrent-abortable-preclean step, in particular the large time (88
and 179secs in the above examples).


Thanks,
Doug.
  

 
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20080418/962a421f/attachment.html