Minor GCs execute faster after first CMS collection

[Jon Masamitsu]

Shane,

Do you ever sees this pattern repeating in
longer runs (ParNew pause times increasing
until a CMS cycle completes)?  There are
three CMS cycles in the log that you sent
the ParNew pause times look stable after the
first CMS cycle.

Jon

On 01/28/10 09:04, Shane Cox wrote:
> 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.
> 
> 
> ------------------------------------------------------------------------
> 
> _______________________________________________
> 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