RFR: JDK-8058944: Unify the time reporting strings in G1 remark

[Bengt Rutisson]

Hi Stefa,

Thanks for looking at this!

On 2016-03-01 10:22, Stefan Johansson wrote:
> Hi Beng
>
> On 2016-03-01 09:47, Bengt Rutisson wrote:
>>
>> Hi all,
>>
>> Could I have  a couple of reviews for this small cleanup to the G1 
>> remark logging?
>>
>> http://cr.openjdk.java.net/~brutisso/8058944/webrev.00/
>> https://bugs.openjdk.java.net/browse/JDK-8058944
>>
>> Currently the remark logging looks like this on debug level:
>>
>> [0,937s][info ][gc,start             ] GC(2) Pause Remark (0,937s)
>> [0,937s][debug][gc,start             ] GC(2) Finalize Marking (0,937s)
>> [0,955s][debug][gc                   ] GC(2) Finalize Marking 
>> (0,937s, 0,955s) 17,949ms
>> [0,955s][debug][gc,start             ] GC(2) GC Ref Proc (0,955s)
>> [0,956s][debug][gc                   ] GC(2) GC Ref Proc (0,955s, 
>> 0,956s) 0,279ms
>> [0,956s][debug][gc,start             ] GC(2) Unloading (0,956s)
>> [0,965s][debug][gc                   ] GC(2) Unloading (0,956s, 
>> 0,965s) 9,623ms
>> [0,965s][debug][gc,start             ] GC(2) GC Aggregate Data (0,965s)
>> [0,966s][debug][gc                   ] GC(2) GC Aggregate Data 
>> (0,965s, 0,966s) 0,614ms
>> [0,966s][info ][gc                   ] GC(2) Pause Remark 
>> 89M->89M(507M) (0,937s, 0,966s) 28,653ms
>>
>>
>> With the proposed change it will look like this:
>>
>> [0,946s][info ][gc,start             ] GC(2) Pause Remark (0,946s)
>> [0,946s][debug][gc,start             ] GC(2) Finalize Marking (0,946s)
>> [0,960s][debug][gc                   ] GC(2) Finalize Marking 
>> (0,946s, 0,960s) 13,677ms
>> [0,960s][debug][gc,start             ] GC(2) Ref Proc (0,960s)
>> [0,961s][debug][gc                   ] GC(2) Ref Proc (0,960s, 
>> 0,960s) 0,524ms
> Should we take this opportunity to improve the "Ref Proc" message even 
> more? "Reference Processing" would look nicer I think. Otherwise the 
> change looks good.

Good point. I changed to "Reference Processing". It now looks like this:

[0,878s][info ][gc,start             ] GC(2) Pause Remark (0,878s)
[0,878s][debug][gc,start             ] GC(2) Finalize Marking (0,878s)
[0,888s][debug][gc                   ] GC(2) Finalize Marking (0,878s, 
0,888s) 10,187ms
[0,888s][debug][gc,start             ] GC(2) Refeference Processing (0,888s)
[0,888s][debug][gc                   ] GC(2) Refeference Processing 
(0,888s, 0,888s) 0,515ms
[0,888s][debug][gc,start             ] GC(2) Unloading (0,888s)
[0,902s][debug][gc                   ] GC(2) Unloading (0,888s, 0,902s) 
13,100ms
[0,902s][debug][gc,start             ] GC(2) Aggregate Data (0,902s)
[0,902s][debug][gc                   ] GC(2) Aggregate Data (0,902s, 
0,902s) 0,387ms
[0,902s][info ][gc                   ] GC(2) Pause Remark 72M->72M(506M) 
(0,878s, 0,902s) 24,406ms

However, there is also a "Ref Proc" and a "Ref Enq" in the "Other" 
section of a normal G1 GC:

[0,913s][info ][gc,phases            ] GC(9)   Other: 1,2ms
[0,913s][debug][gc,phases            ] GC(9)     Choose CSet: 0,0ms
[0,913s][debug][gc,phases            ] GC(9)     Preserve CM Refs: 0,1ms
[0,913s][debug][gc,phases            ] GC(9)     Ref Proc: 0,1ms
[0,913s][debug][gc,phases            ] GC(9)     Ref Enq: 0,0ms
[0,913s][debug][gc,phases            ] GC(9)     Redirty Cards: 0,1ms
[0,913s][debug][gc,phases            ] GC(9)     Humongous Register: 0,0ms
[0,913s][debug][gc,phases            ] GC(9)     Humongous Reclaim: 0,0ms


I change those as well:

[0,868s][info ][gc,phases            ] GC(9)   Other: 0,9ms
[0,868s][debug][gc,phases            ] GC(9)     Choose CSet: 0,0ms
[0,868s][debug][gc,phases            ] GC(9)     Preserve CM Refs: 0,2ms
[0,868s][debug][gc,phases            ] GC(9)     Reference Processing: 0,0ms
[0,868s][debug][gc,phases            ] GC(9)     Reference Enqueuing: 0,0ms
[0,868s][debug][gc,phases            ] GC(9)     Redirty Cards: 0,1ms
[0,868s][debug][gc,phases            ] GC(9)     Humongous Register: 0,0ms
[0,868s][debug][gc,phases            ] GC(9)     Humongous Reclaim: 0,0ms

Here's an updated webrev:
http://cr.openjdk.java.net/~brutisso/8058944/webrev.01/

If you find this ok I will change the title of the bug report to be 
"Unify the reporting strings for the GC debug level logging in G1" since 
it no longer concerns just the remark phase.

Thanks,
Bengt

>
>
> Thanks,
> Stefan
>
>> [0,961s][debug][gc,start ] GC(2) Unloading (0,961s)
>> [0,972s][debug][gc                   ] GC(2) Unloading (0,961s, 
>> 0,972s) 11,425ms
>> [0,972s][debug][gc,start             ] GC(2) Aggregate Data (0,972s)
>> [0,972s][debug][gc                   ] GC(2) Aggregate Data (0,972s, 
>> 0,972s) 0,377ms
>> [0,972s][info ][gc                   ] GC(2) Pause Remark 
>> 62M->62M(506M) (0,946s, 0,972s) 26,243ms
>>
>>
>> Thanks,
>> Bengt
>