CMSScavengeBeforeRemark confuses CMS-remark time

[Rozdev29]

Hi there
Is this bug fixed for java 6 or 7?
Which version will have this fix?

Thanks
Saroj



On Aug 29, 2012, at 7:43 AM, "Michal Frajt" <michal at frajt.eu> wrote:

> Hi,
> 
> We have fixed the bug in the CMSWaitDuration handling (find more in the 'CMSWaitDuration unstable behavior' hotspot-gc-dev post, fixed done in our customized OpenJDK). The CMS-initial-mark phase is now always starting right after the scavenge which makes it running 20-50 faster. Currently we are focused on minimizing the cost of the second STW remark phase. There we have the option CMSScavengeBeforeRemark to invoke the scavenge right before the remarking. All works as expected but the results reported in CMS GC logs are a bit confusing.  
> 
> The CMSScavengeBeforeRemark forces scavenge invocation from the CMS-remark phase (from within the VM thread as the CMS-remark operation is executed in the foreground collector). The generation collector reports its time into the same GC log file. In our case the ParNew collector reports the line including the STW time (0.0266193 seconds here).
> 
>  2012-08-29T07:27:02.613+0200: 9.388: [GC 9.388: [ParNew Desired survivor size 9568256 bytes, new threshold 8 (max 8) - age   1:    4626512 bytes,    4626512 total : 65631K->14657K(112384K), 0.0264694 secs] 108213K->72304K(10467072K), 0.0266193 secs] [Times: user=0.17 sys=0.01, real=0.03 secs]
> 
>  
> The total CMS-remark time (STW) is usually understood as the number of seconds reported by the CMS-remark line (0.401657 seconds here).
> 
>  9.415: [Rescan (parallel)  (Survivor:10chunks) .... 0.0064098 secs]9.421: [weak refs processing, 0.0000320 secs]9.421: [class unloading, 0.0020331 secs]9.423: [scrub symbol & string tables, 0.0042518 secs] [1 CMS-remark: 57647K(10354688K)] 72304K(10467072K), 0.0401657 secs] [Times: user=0.23 sys=0.01, real=0.04 secs]
> 
>  
> 
> 
> But, in the case the ParNew got invoked explicitly by the CMSScavengeBeforeRemark option, the time reported by the CMS-remark phase does include the time of the generation collector. The common interpretation is that there was one ParNew STW (0.0266193 sec) and the CMS-remark STW (0.0401657 secs) phase. Fortunately the total STW time is not ParNew plus CMS-remark time but only the CMS-remark time in total. In our example we spent 27ms in the ParNew and 14ms in the CMS-remark. The total STW time was 40ms and not 67ms as many times wrongly interpreted. 
> 
> The reporting of the CMS-remark phase, when used together with the CMSScavengeBeforeRemark option, does not allow easy interpretation of the application STW times. None of the CMS log file analyzer tools is able to correctly interpret the time reported in the CMS-remark phase. As far as we know none of existing interpretations of the CMS logging outputs does mention this issue. Same way the fixed CMSWaitDuration was able to deliver 20-50 faster initial marking to us, the existing and working CMSScavengeBeforeRemark option is able to deliver similar results when correctly interpreted from the GC log files. 
> 
> Regards,
> Michal
> 
>  
> 
>  
> 
> _______________________________________________
> hotspot-gc-use mailing list
> hotspot-gc-use at openjdk.java.net
> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20120829/486e4496/attachment.html