Avoiding 1 long CMS with a big heap

[Y. Srinivas Ramakrishna]

Right, this is a performance bug in CMS in general (init
mark is single-threaded) and is exacerbated by iCMS (because
of the way the init-mark is scheduled currently between scavenges
so as to temporally separate pauses). Just drop the incremental
option and you would be fine in this case.

I'll annotate an existing bug for long init mark pauses
with this info about the pathology being exacerbated
by iCMS .... and see if we can fix it sooner ...

-- ramki

On 04/14/10 10:37, Jon Masamitsu wrote:
> 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

_______________________________________________
hotspot-gc-use mailing list
hotspot-gc-use at openjdk.java.net
http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use