CMS GC tuning under JVM 5.0

[Y Srinivas Ramakrishna]

> > 31680.017: [CMS-concurrent-mark: 0.477/0.477 secs]

> > 31680.023: [CMS-concurrent-preclean: 0.006/0.006 secs]

> > secs]31768.430: [CMS31768.430: [CMS-concurrent-abortable-preclean: 
> > 5.410/88.406 secs]

> > 100080.381: [CMS-concurrent-mark: 0.494/0.494 secs]

> > 100080.390: [CMS-concurrent-preclean: 0.009/0.009 secs]

> > secs]100259.694: [CMS100259.695: [CMS-concurrent-abortable-preclean: 
> 
> > 10.649/179.305 sec
> >
> > s]

Just to add a bit to what Jon said, the notation [CMS-concurrent-xxx:  yyy/zzz secs]
indicates that the CMS concurrent xxx-phase took roughly zzz secs of wall-clock
elapsed time, of which yyy secs of accumulated elapsed time was spent by the
CMS thread doing that work; the remainder of the time, zzz - yyy secs, the
thread was either sleeping or was stalled for a lock. Note that yyy secs is
a rough upper bound of the lwp-virtual time, but the thread need not necessarily
have been on-proc all of that time.

So in particular, in the last display, of the 179 secs of elapsed time the CMS thread
was actually sleeping for 169 secs. Jon's conjecture of the bug about CMSMaxAbortablePrecleanTime
seems to be the most likely explanation. (There was a confusion with the interpretation
of the units, treating an intended ms spec as a seconds spec, the documented
workaround is to set the value to a value in seconds not exceeding about 5:
-XX:CMSMaxAbortablePrecleanTime=5 -- or to zero to just elide that phase.)

I believe this has been fixed in some later version of JDK 5uXX, but am unable to
check the bug id at the moment.

-- ramki