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

[John Cuthbertson]

Hi Ramki,

Thanks for looking. The time does include the cleaning of the string and 
symbol tables. I'll reduce the scope of the timer and change output. The 
reason why I chose that output was in case PrintReferenceGC was on by 
itself. So changing the output will change what flags are used to set 
verbose to something like "(PrintGC || PrintGCDetails) && PrintReferenceGC.

JohnC

On 07/20/11 15:44, Y. S. Ramakrishna wrote:
> 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