G1GC Full GCs

[Todd Lipcon]

On Wed, Jul 7, 2010 at 12:49 AM, Todd Lipcon <todd at cloudera.com> wrote:

>
> It would
>>> be instructive to see what the comparable CMS logs look like.
>>> May be then you could start with the same heap shapes for the
>>> two and see if you can get to the bottom of the full gc (which
>>> as i understand you get to more quickly w/G1 than you did
>>> w/CMS).
>>>
>>
>> Yep, I'll kick off some CMS tests this evening and get back to you with
>> those logs.
>>
>>
> The CMS logs are up at:
>
> http://cloudera-todd.s3.amazonaws.com/cms-log.txt
>
> The actual application activity starts at 00:15:50 or so - this is when I
> started up the benchmark clients. Before that, the process was essentially
> idle. If it would be helpful to rerun with more verbose options like
> tenuring output, I can do so. Also happy to provide heap dumps - this is
> just a benchmark with artificial data.
>

Overnight I saw one "concurrent mode failure". Here's the section of logs
leading up to it:

2010-07-07T07:56:26.953-0700: 28489.370: [CMS-concurrent-mark: 1.880/2.253
secs] [Times: user=16.08 sys=0.65, real=2.25 secs]
2010-07-07T07:56:26.953-0700: 28489.370: [CMS-concurrent-preclean-start]
2010-07-07T07:56:26.978-0700: 28489.395: [GC 28489.395: [ParNew:
59004K->6528K(59008K), 0.0186670 secs] 6371506K->6323755K(8382080K),
0.0187590 secs] [Times: user=0.16 sys=0.01, real=0.02 secs]
2010-07-07T07:56:27.060-0700: 28489.477: [GC 28489.477: [ParNew:
59008K->6527K(59008K), 0.0169360 secs] 6376235K->6330593K(8382080K),
0.0170350 secs] [Times: user=0.17 sys=0.00, real=0.02 secs]
2010-07-07T07:56:27.141-0700: 28489.558: [GC 28489.558: [ParNew:
57956K->6528K(59008K), 0.0184100 secs] 6382021K->6337204K(8382080K),
0.0185230 secs] [Times: user=0.17 sys=0.00, real=0.01 secs]
2010-07-07T07:56:27.218-0700: 28489.634: [GC 28489.634: [ParNew:
58929K->6528K(59008K), 0.2090130 secs] 6389605K->6345481K(8382080K),
0.2091010 secs] [Times: user=2.28 sys=0.01, real=0.21 secs]
2010-07-07T07:56:27.478-0700: 28489.894: [GC 28489.895: [ParNew:
58968K->6528K(59008K), 0.0175530 secs] 6397922K->6352489K(8382080K),
0.0176710 secs] [Times: user=0.17 sys=0.00, real=0.02 secs]
2010-07-07T07:56:27.546-0700: 28489.963: [GC 28489.963: [ParNew:
59004K->6528K(59008K), 0.0163740 secs] 6404965K->6357350K(8382080K),
0.0164930 secs] [Times: user=0.15 sys=0.00, real=0.02 secs]
2010-07-07T07:56:27.613-0700: 28490.030: [GC 28490.030: [ParNew:
58967K->6528K(59008K), 0.0234590 secs] 6409789K->6361980K(8382080K),
0.0235860 secs] [Times: user=0.22 sys=0.00, real=0.02 secs]
2010-07-07T07:56:27.696-0700: 28490.113: [GC 28490.113: [ParNew:
58974K->6528K(59008K), 0.0132980 secs] 6414427K->6364893K(8382080K),
0.0133890 secs] [Times: user=0.15 sys=0.01, real=0.01 secs]
2010-07-07T07:56:27.786-0700: 28490.203: [GC 28490.203: [ParNew (promotion
failed): 59008K->59008K(59008K), 0.0179250 secs]28490.221:
[CMS2010-07-07T07:56:27.901-0700: 28490.317: [CMS-concurrent-preclean:
0.556/0.947 secs] [Times:
 user=5.76 sys=0.26, real=0.95 secs]
 (concurrent mode failure): 6359176K->4206871K(8323072K), 17.4366220 secs]
6417373K->4206871K(8382080K), [CMS Perm : 18609K->18565K(31048K)],
17.4546890 secs] [Times: user=11.17 sys=0.09, real=17.45 secs]

I've interpreted pauses like this as being caused by fragmentation, since
the young gen is 64M, and the old gen here has about 2G free. If there's
something I'm not understanding about CMS, and I can tune it more smartly to
avoid these longer pauses, I'm happy to try.

Thanks
-Todd

-- 
Todd Lipcon
Software Engineer, Cloudera
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20100707/fc8977df/attachment-0001.html