RFR (XXXS): 7068215: G1: Print reference processing time during remark

[Y. S. Ramakrishna]

John -- isn't the new timer capturing more than just reference
processing? It's including string table and symbol table
walks as well. I'd much rather you dropped the redundant "GC remark"
(after all it's already there in the outer print scope)
and limited the timer to a scope that exactly captures
reference processing and enqueueing (i.e. not the string
and symbol table walks). That extra probably explains the
missing ~9 ms time in your last display below?

-- ramki

On 07/20/11 15:15, John Cuthbertson wrote:
> Hi Everyone,
> 
> Can I have a couple of volunteers review this small change? The webrev 
> can be found at: http://cr.openjdk.java.net/~johnc/7068215/webrev.0/
> 
> Background:
> During some recent performance runs of G1, some extremely long remark 
> pauses (espccially the first) were observed and the CPU times indicated 
> that the remarks were pretty serial. There is speculation that these 
> long remarks are caused be the reference process, which is serial by 
> default. This CR is to add a timer to the reference processing to 
> confirm our suspicions. With the new timer, the output format of the 
> remark has changed a little (new output is in *bold*):
> 
> _PrintGC (only)_
> 13.061: [GC pause (young) (initial-mark) 19M->9983K(32M), 0.0108699 secs]
> 13.072: [GC concurrent-mark-start]
> 13.120: [GC concurrent-mark-end, 0.0484379 sec]
> 13.122: [GC remark, 0.0265762 secs]
> 13.154: [GC concurrent-count-start]
> 13.160: [GC concurrent-count-end, 0.0058944]
> 13.160: [GC cleanup 10M->10M(32M), 0.0004928 secs]
> 
> No difference from before.
> 
> _PrintGC + PrintReferenceGC_
> 14.537: [GC pause (young) (initial-mark) 19M->10146K(32M), 0.0110351 secs]
> 14.548: [GC concurrent-mark-start]
> 14.596: [GC concurrent-mark-end, 0.0474622 sec]
> 14.596: [GC remark *14.596: [GC remark (ref processing), 0.0274587 
> secs]*, 0.0277831 secs]
> 14.624: [GC concurrent-count-start]
> 14.630: [GC concurrent-count-end, 0.0059460]
> 14.630: [GC cleanup 10M->10M(32M), 0.0004955 secs]
> 
> _PrintGCDetails (only)_
> 21.336: [GC concurrent-mark-end, 0.0394013 sec]
> 21.336: [GC remark *21.347: [GC remark (ref processing), 0.0262900 
> secs]*, 0.0376863 secs]
>  [Times: user=0.07 sys=0.00, real=0.04 secs]
> 21.374: [GC concurrent-count-start]
> 21.380: [GC concurrent-count-end, 0.0059530]
> 21.380: [GC cleanup 10M->10M(32M), 0.0004814 secs]
> 
> The CPU times after the remark are for the remark pause as a whole. 
> Using the new output (either the delta between the timestamps or the 
> delta between the times) we can synthesize the amount of time it took 
> for the actual marking part of the remark pause.
> 
> _PrintGCDetails + PrintReferenceGC_
> 12.450: [GC concurrent-mark-end, 0.0390687 sec]
> 12.450: [GC remark *12.452: [GC remark (ref processing)*12.452: 
> [SoftReference, 0 refs, 0.0000226 secs]12.453: [WeakReference, 9 refs, 
> 0.0000216 secs]12.453: [FinalReference, 15279 refs, 0.0189796 
> secs]12.472: [PhantomReference, 0 refs, 0.0000072 secs]12.472: [JNI Weak 
> Reference, 15 refs, 0.0000072 secs], *0.0272514 secs]*, 0.0295062 secs]
>  [Times: user=0.04 sys=0.00, real=0.03 secs]
> 12.480: [GC concurrent-count-start]
> 12.486: [GC concurrent-count-end, 0.0059510]
> 12.486: [GC cleanup 10M->10M(32M), 0.0005403 secs]
>  [Times: user=0.00 sys=0.00, real=0.00 secs]
> 
> Thanks,
> 
> JohnC