unexplained CMS pauses

Y.S.Ramakrishna at Sun.COM Y.S.Ramakrishna at Sun.COM
Mon Sep 28 10:13:18 PDT 2009


What platform are you on (#cpu's etc.)
and when you say "app reports a pause of 300 ms"
is it that the odd transaction sees a latency
of 300 ms (coincident with concurrent mark),
whereas most transactions complete much more
quickly?

I am trying to first understand how you determine
that the application is seeing "long pauses"
when a minor gc occurs during concurrent mark.

PS: for example, if two gc pauses (say a scavenge of 30 ms
and an initial mark of 13 ms occur in quick succession,
your application might notice a  pause of 43 ms, etc.)

-- ramki

On 09/28/09 10:07, Shane Cox wrote:
> Our application is reporting long pauses when a minor GC occurs during 
> the Concurrent Mark phase of CMS.  The output below is a specific 
> example.  All of the GC pauses are less than 30ms (initial mark, remark, 
> minor GC).  However, our app reported a 300ms pause.
> 
> 56750.934: [GC [1 CMS-initial-mark: 702464K(1402496K)] 
> 719045K(1551616K), 0.0131859 secs]
> 56750.947: [CMS-concurrent-mark-start]
> 56752.133: [GC 56752.133: [ParNew: 144393K->12122K(149120K), 0.0237615 
> secs] 846857K->719330K(1551616K), 0.0239988 secs]
> 56752.162: [CMS-concurrent-mark: 1.188/1.215 secs]
> 56752.162: [CMS-concurrent-preclean-start]
> 56752.243: [CMS-concurrent-preclean: 0.070/0.081 secs]
> 56752.243: [CMS-concurrent-abortable-preclean-start]
> 56752.765: [CMS-concurrent-abortable-preclean: 0.143/0.522 secs]
> 56752.766: [GC[YG occupancy: 77423 K (149120 K)]56752.766: [Rescan 
> (parallel) , 0.0065730 secs]56752.773: [weak refs processing, 0.0001983 
> secs] [1 CMS-remark: 707208K(1402496K)] 784631K(1551616K), 0.0068908 secs]
> 56752.773: [CMS-concurrent-sweep-start]
> 56753.209: [CMS-concurrent-sweep: 0.436/0.436 secs]
> 56753.209: [CMS-concurrent-reset-start]
> 56753.219: [CMS-concurrent-reset: 0.010/0.010 secs]
> 
> 
> We only observe this behavior when a minor GC occurs during the 
> Concurrent Mark (which is rare).  Our app has reported pauses up to 1.2 
> seconds ... which is generally the time it takes to perform a Concurrent 
> Mark.
> 
> 
> Any insight/help that you could provide would be much appreciated.
> 
> Thanks



More information about the hotspot-gc-dev mailing list