Minor GCs execute faster after first CMS collection

[Shane Cox]

Could anyone explain why Minor GCs execute faster after the first CMS
collection completes?  I'm running a fairly steady state test and observe
100-200ms Minor GC pauses at the beginning:
2010-01-28T11:45:23.152-0500: 450.374: [GC 450.374: [ParNew:
74560K->10624K(74560K), 0.1361412 secs] 963986K->908709K(1898112K),
0.1362816 secs] [Times: user=0.12 sys=0.12, real=0.14 secs]
2010-01-28T11:45:25.921-0500: 453.144: [GC 453.144: [ParNew:
74560K->10624K(74560K), 0.1757643 secs] 972645K->919770K(1898112K),
0.1759141 secs] [Times: user=0.14 sys=0.15, real=0.18 secs]
2010-01-28T11:45:28.921-0500: 456.143: [GC 456.143: [ParNew:
74560K->10624K(74560K), 0.1516837 secs] 983706K->929407K(1898112K),
0.1518258 secs] [Times: user=0.13 sys=0.13, real=0.15 secs]

Then a CMS collection executes:
2010-01-28T11:45:29.074-0500: 456.296: [GC [1 CMS-initial-mark:
918783K(1823552K)] 930044K(1898112K), 0.0084243 secs] [Times: user=0.01
sys=0.00, real=0.01 secs]
......
2010-01-28T11:45:33.587-0500: 460.809: [CMS-concurrent-reset: 0.012/0.012
secs] [Times: user=0.01 sys=0.00, real=0.01 secs]



After the CMS collection, Minor GC pause times drop to 25-35ms:
2010-01-28T11:45:34.196-0500: 461.418: [GC 461.418: [ParNew:
74560K->10624K(74560K), 0.0349928 secs] 527737K->475222K(1898112K),
0.0351559 secs] [Times: user=0.11 sys=0.00, real=0.04 secs]
2010-01-28T11:45:36.641-0500: 463.863: [GC 463.863: [ParNew:
74560K->10624K(74560K), 0.0300849 secs] 539158K->484716K(1898112K),
0.0302200 secs] [Times: user=0.09 sys=0.00, real=0.03 secs]
2010-01-28T11:45:39.081-0500: 466.304: [GC 466.304: [ParNew:
74560K->10624K(74560K), 0.0300672 secs] 548652K->494809K(1898112K),
0.0302327 secs] [Times: user=0.09 sys=0.00, real=0.03 secs]


The only thing that stands out to me is "sys" time which drops to zero after
the CMS collection.

I'm guessing that an adjustment/optimization is being made after the CMS
collection, but don't know what.  Any help/ideas would be appreciated.

Thanks


Full GC log attached.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20100128/2e801716/attachment.htm>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: 2010-01-28-RouterPTFX021_gc-output.log.gz
Type: application/x-gzip
Size: 23892 bytes
Desc: not available
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20100128/2e801716/2010-01-28-RouterPTFX021_gc-output.log.gz>
-------------- next part --------------
_______________________________________________
hotspot-gc-use mailing list
hotspot-gc-use at openjdk.java.net
http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use