Avoiding 1 long CMS with a big heap

[Jon Masamitsu]

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
there.

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

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 
-XX:+CMSScavengeBeforeRemark
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
http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use