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

[Tony Printezis]

John,

FWIW: AFAIK there are no other GC pauses that generate -start / -end 
output. Currently, all the output generated during a pause is included 
in the [GC ... ] line for the pause. Not 100% sure what the best 
approach here is. Stay consistent with previous output or make the 
output more sensible?

Tony

John Cuthbertson wrote:
> Hi All,
>
> The main reason was that I wanted to use the TraceTime class (as other 
> GCs and other parts of G1s). As Ramki, pointed out, however, this also 
> ends up including the time for cleaning up the symbol and string 
> tables unless an inner scope is used. Igor also makes a good point in 
> that with his proposed format all you need to is grep for "[GC X-end" 
> to get the times of the event(s) X that you are interested in.
>
> With that in mind a new webrev for Igor's format is at 
> http://cr.openjdk.java.net/~johnc/7068215/webrev.1/
>
> With these changes, the output looks like:
>
> PrintGC:
> 9.404: [GC concurrent-mark-start]
> 9.470: [GC concurrent-mark-end, 0.0666473 sec]
> 9.471: [GC remark-start]
> 9.480: [GC remark-end, 0.0089202 secs]
> 9.480: [GC concurrent-count-start]
> 9.489: [GC concurrent-count-end, 0.0090631]
> 9.489: [GC cleanup-start]
> 9.490: [GC cleanup-end 29M->26M(64M), 0.0011680 secs]
> 9.491: [GC concurrent-cleanup-start]
> 9.491: [GC concurrent-cleanup-end, 0.0001412]
>
> Remark and cleanup now have start and end markers; the heap size 
> transition for the cleanup is on the end marker.
>
> PrintGC + PrintGCDetails:
> 8.133: [GC remark-start]
> 8.148: [GC remark-end, 0.0151136 secs]
> [Times: user=0.04 sys=0.00, real=0.02 secs]
> 8.148: [GC concurrent-count-start]
> 8.156: [GC concurrent-count-end, 0.0076754]
> 8.198: [GC cleanup-start]
> 8.199: [GC cleanup-end 33M->31M(64M), 0.0009878 secs]
> [Times: user=0.01 sys=0.00, real=0.00 secs]
> 8.199: [GC concurrent-cleanup-start]
> 8.199: [GC concurrent-cleanup-end, 0.0001300]
>
> The only addition here is the printing of the CPU times for remark and 
> cleanup (as it was before).
>
> PrintGC + PrintReferenceGC:
> 8.070: [GC concurrent-mark-start]
> 8.117: [GC concurrent-mark-end, 0.0460792 sec]
> 8.219: [GC remark-start]
> 8.229: [GC ref-processing-start]
> 8.230: [GC ref-processing-end, 0.0019488 secs]
> 8.235: [GC remark-end, 0.0158816 secs]
> 8.235: [GC concurrent-count-start]
> 8.257: [GC concurrent-count-end, 0.0220724]
> 8.306: [GC cleanup-start]
> 8.307: [GC cleanup-end 28M->25M(64M), 0.0007636 secs]
> 8.307: [GC concurrent-cleanup-start]
> 8.319: [GC concurrent-cleanup-end, 0.0120578]
>
> With the addition of PrintReferenceGC we get the start and end markers 
> of the ref-processing phase.
>
> PrintGC + PrintGCDetails + PrintReferenceGC;
>
> 8.008: [GC remark-start]
> 8.014: [GC ref-processing-start]
> 8.014: [SoftReference, 0 refs, 0.0000186 secs]
> 8.014: [WeakReference, 383 refs, 0.0002477 secs]
> 8.014: [FinalReference, 783 refs, 0.0012285 secs]
> 8.016: [PhantomReference, 156 refs, 0.0001268 secs]
> 8.016: [JNI Weak Reference, 86 refs, 0.0000083 secs]
> 8.016: [GC ref-processing-end, 0.0022400 secs]
> 8.021: [GC remark-end, 0.0132204 secs]
> [Times: user=0.03 sys=0.00, real=0.01 secs]
> 8.021: [GC concurrent-count-start]
> 8.030: [GC concurrent-count-end, 0.0088910]
> 8.030: [GC cleanup-start]
> 8.031: [GC cleanup-end 29M->26M(64M), 0.0008376 secs]
> [Times: user=0.00 sys=0.00, real=0.00 secs]
> 8.031: [GC concurrent-cleanup-start]
> 8.031: [GC concurrent-cleanup-end, 0.0001300]
>
> The output of the other collectors are unchanged.
>
> Thanks,
>
> JohnC
>
> On 07/25/11 11:09, Tony Printezis wrote:
>> 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
>>>>
>>>
>