CMS CMF

[Kirk Pepperdine]

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