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

[John Cuthbertson]

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
>>>
>>