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

[John Cuthbertson]

Hi Everyone,

I have a new webrev of the original output based upon feed back from 
Ramki at http://cr.openjdk.java.net/~johnc/7068215/webrev.2/. I'm still 
looking for one more reviewer.

Thanks,

JohnC

On 07/20/11 15:55, 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
>