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

Bengt Rutisson bengt.rutisson at oracle.com
Tue Mar 1 10:03:00 UTC 2016


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
>



More information about the hotspot-gc-dev mailing list