Avoiding 1 long CMS with a big heap

Jon Masamitsu jon.masamitsu at oracle.com
Wed Apr 14 10:37:19 PDT 2010

On 04/14/10 07:24, Matt Khan wrote:
> 2010-04-13T22:47:09.067+0000: 2242.850: [GC 2242.851: [ParNew
> Desired survivor size 14745600 bytes, new threshold 1 (max 1)
> - age   1:    7803368 bytes,    7803368 total
> : 16359981K->12388K(16368000K), 0.0589077 secs] 
> 16363570K->24406K(16564608K) icms_dc=5 , 0.0593692 secs] [Times: user=0.18 
> sys=0.06, real=0.06 secs] 
> 2010-04-13T23:05:29.072+0000: 3342.854: [GC [1 CMS-initial-mark: 
> 12018K(196608K)] 7811496K(16564608K), 4.2147116 secs] [Times: user=4.15 
> sys=0.06, real=4.22 secs] 
I'm assuming that there was no GC activity between the ParNew collection and
the initial-mark above.

That says that the application has been filling up the young gen for a 
while.  Most of that might
be dead when the initial-mark starts but we don't know so we have to 
assume that it's live.
Live objects in the young gen can keep objects alive in the tenured 
(cms) generation so
we need to look at the young gen and your young gen is large so there's 
lots of GC work

The first initial-mark had a full GC just before it (right?) so the 
young gen was likely

If you run your test case longer and see mostly longer initial-marks, 
that would suggest
that my guess is right.
> 2010-04-13T23:05:33.288+0000: 3347.070: [CMS-concurrent-mark-start]
> 2010-04-13T23:05:33.343+0000: 3347.125: [CMS-concurrent-mark: 0.048/0.056 
> secs] [Times: user=0.35 sys=0.15, real=0.06 secs] 
> 2010-04-13T23:05:33.344+0000: 3347.126: [CMS-concurrent-preclean-start]
> 2010-04-13T23:05:33.347+0000: 3347.128: [CMS-concurrent-preclean: 
> 0.003/0.003 secs] [Times: user=0.01 sys=0.01, real=0.00 secs] 
> 2010-04-13T23:05:33.347+0000: 3347.129: 
> [CMS-concurrent-abortable-preclean-start]
>  CMS: abort preclean due to time 2010-04-13T23:05:38.456+0000: 3352.238: 
> [CMS-concurrent-abortable-preclean: 0.573/5.109 secs] [Times: user=0.94 
> sys=0.24, real=5.11 secs] 
> 2010-04-13T23:05:38.461+0000: 3352.243: [GC[YG occupancy: 7824966 K 
> (16368000 K)]3352.243: [Rescan (parallel) , 4.2295340 secs]3356.473: [weak 
> refs processing, 0.0000422 secs] [1 CMS-remark: 12018K(196608K)] 
> 7836984K(16564608K), 4.2298963 secs] [Times: user=36.56 sys=1.65, 
> real=4.23 secs] 
Also note that your remark pause is long.  If you add 
it will schedule a ParNew collection before the remark.  If this causes 
the remark pause
to drop significantly, that also suggests that the issue is just lots of 
work with
lots of live objects in the young gen (because the ParNew collection 
will reduce the
number of live objects in the young gen).

hotspot-gc-use mailing list
hotspot-gc-use at openjdk.java.net

More information about the hotspot-gc-dev mailing list