CMS CMF

[Srinivas Ramakrishna]

You probably have CMSScavengeBeforeRemark Enabled. The scavenge fails when
initiated from the remark, but i am guessing that the failure is ignored
and the remark ploughs on (slowly!). Then a full gc is attempted, but by
then a sweep has started and for historical reasons it completes before the
full gc can proceed. This points out several malinteractions in the case of
CMSScavengeBeforeRemark that had not been fully considered by me when i
designed it. In general, having more finely interruptible phases would have
been better for CMS (as comments in the code state).... I think a simple
fix is to not attempt the remark if the scavenge failed and just bail to a
stop-world GC at that point. I think the change would not be too difficult.
Please file a bug.

-- ramki

On Fri, Oct 19, 2012 at 2:07 PM, Kirk Pepperdine <kirk at kodewerk.com> wrote:

> Hi all,
>
> I've got this GC log fragment that I'm puzzling over.
>
> 2833.756: [GC[YG occupancy: 1600484 K (1887488 K)]2833.756: [GC 2833.757:
> [ParNew (promotion failed): 1600484K->1600484K(1887488K), 2.2601630 secs]
> 19739658K->20165811K(20761856K), 2.2605170 secs] [Times: user=10.47
> sys=0.11, real=2.26 secs]
> 2836.017: [Rescan (parallel) , 2.2167670 secs]2838.234: [weak refs
> processing, 0.5441620 secs]2838.778: [class unloading, 0.0623720
> secs]2838.841: [scrub symbol & string tables, 0.0079860 secs] [1
> CMS-remark: 18565327K(18874368K)] 20165811K(20761856K), 5.1880910 secs]
> [Times: user=42.02 sys=0.25, real=5.19 secs]
> 2838.945: [CMS-concurrent-sweep-start]
> 2849.966: [Full GC 2849.966: [CMS2862.696: [CMS-concurrent-sweep:
> 19.533/23.751 secs] [Times: user=42.67 sys=4.29, real=23.75 secs]
>  (concurrent mode failure): 17074814K->4842456K(18874368K), 41.9426500
> secs] 18962302K->4842456K(20761856K), [CMS Perm : 65645K->65265K(109292K)],
> 41.9429740 secs]
>
> So, a ParNew is signaled @ 2833.757 which leads to a promotion failed. I
> would expect that @ 2833.757 + 2.26 or 2836.017 we'd see the concurrent
> mode failure being reported. However @ that time we instead see a
> Rescan/remark. The CMS finally comes @ 2849.966, more than 15 seconds after
> the allocation failure has been reported. Is there a change here in that
> the final phases of CMS were allowed to run rather than reverting to a Full
> GC or is there something else going on here that I've missed on.
>
> Regards,
> Kirk
>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20121019/47b5f7c9/attachment.htm>