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

[Tony Printezis]

Igor,

(I'm just back from vacation, not sure whether you guys discussed this 
further...)

I'd guess that John took the approach he did because this is what the 
other GCs also do (and also because ref processing is part of the remark 
work too). The output below does miss the latter point I think.

Tony

Igor Veresov wrote:
> Shouldn't be the log structured more like?
> #ts: [GC remark-start]
> #ts: [GC ref-processing-start]
> #ts: [GC *References, #t sec]
> #ts: [GC ref-processing-end, #t sec]
> #ts: [GC remark-end, #t sec]
>
> Otherwise the parser would have to support recursive expressions and I 
> think it's also easier to parse for humans if it's linear. I'm not 
> insisting though.
>
> igor
>
> On 7/20/11 3:55 PM, John Cuthbertson wrote:
>> 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
>>
>