Request for review (S): 7161545: G1: Minor cleanups to the G1 logging

[Bengt Rutisson]

Hi all,

I still only have one reviewer (Thanks John Cu!) for this change. Anyone 
else feel like taking a look?

Bengt


On 2012-04-26 23:47, John Cuthbertson wrote:
> Hi Bengt,
>
> Thanks for making the changes - looks good to me. And converting 
> no_of_workers etc to an unsigned as a separate CR is fine.
>
> JohnC
>
> On 04/25/12 05:42, Bengt Rutisson wrote:
>>
>> Hi John,
>>
>> Thanks for looking at this!
>>
>> Here's an updated webrev based on your comments:
>> http://cr.openjdk.java.net/~brutisso/7161545/webrev.01/
>>
>> I did not fix all of your comment. See my comments inline.
>>
>> On 2012-04-24 01:36, John Cuthbertson wrote:
>>> Hi Bengt,
>>>
>>> This looks good to me. A couple of suggestions for your consideration:
>>>
>>> * Looking at the code, it occurred to me that 
>>> G1CollectorPolicy::print_par_stats() and 
>>> G1CollectorPolicy::print_par_sizes()  are very similar. If you 
>>> passed the format string in as a parameter and permitted the order 
>>> in print_par_sizes() to match that in print_par_stats() (which it 
>>> probably should) then they could be coalesced into a single routine 
>>> (or a base routine and two callers).
>>
>> It is not really enough to just pass the format string since we also 
>> need to cast the values. Also, it is kind of strange to me to have 
>> the format string specified in one place and passing values to it in 
>> another place.
>>
>> However, you are definitely correct about the code duplication. I 
>> tried a different solution and added a parameter to the 
>> print_par_stats() to allow it to choose between the two format 
>> strings. What do you think about that?
>>
>>> * Did you consider extending the current version of 
>>> G1CollectorPolicy::print_stats() to take an additional, optional 
>>> (with a default value of NULL) extra_info parameter?
>>
>> Don't think this adds much value. The print_stats() methods are one 
>> liners so I don't think the code would be much simpler by doing this.
>>
>>> * Shouldn't 'workers' be an unsigned? Simlarly for no_of_gc_threads 
>>> (parameter and field of G1CollectorPolicy), and active_workers at 
>>> the call site of G1CollectorPolicy::record_collection_pause_end()?
>>
>> You are right, but g1CollectorPolicy is full of "int workers" so I 
>> don't think we should change that as part of this checkin. Should I 
>> file a separate CR to change all occurrences of "int workers" to 
>> "uint workers" in g1CollectorPolicy?
>>
>>> * Did you consider templatizing bytesize_in_proper_unit()?
>>
>> Good idea! I did that.
>>
>> Thanks again for looking at this!
>> Bengt
>>
>>
>>>
>>> JohnC
>>>
>>> On 04/16/12 02:32, Bengt Rutisson wrote:
>>>>
>>>> Hi all,
>>>>
>>>> Could I have a couple of reviews for this?
>>>> http://cr.openjdk.java.net/~brutisso/7161545/webrev.00
>>>>
>>>> This includes four minor cleanups of the G1 logging:
>>>>
>>>> * Rename "to-space-overflow" to "to-space-exhausted"
>>>> * Introduce one decimal point in the size format
>>>> * Add Sum to the aggregate and re-order the entries
>>>> * Add number of GC workers to the log output
>>>>
>>>> I also added gigabyte conversion to proper_unit_for_byte_size() and 
>>>> byte_size_in_proper_unit(). I hope that makes sense. It is not 
>>>> strictly necessary for this change, but I think it makes sense. I'm 
>>>> fine with leaving it out or pushing it as a separate change.
>>>>
>>>>
>>>> After the change logging on the finest level will look like this:
>>>>
>>>> [GC pause (young), 0.00447433 secs]
>>>>    [Parallel Time: 3.3 ms, GC Workers: 4]
>>>>       [GC Worker Start (ms):  31098.2  31098.2  31098.3  31098.3
>>>>        Min: 31098.2, Avg: 31098.2, Max: 31098.3, Diff: 0.1, Sum: 
>>>> 124392.9]
>>>>       [Ext Root Scanning (ms):  2.2  2.4  2.0  2.5
>>>>        Min: 2.0, Avg: 2.3, Max: 2.5, Diff: 0.6, Sum: 9.1]
>>>>       [Update RS (ms):  0.2  0.0  0.3  0.0
>>>>        Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.3, Sum: 0.5]
>>>>          [Processed Buffers : 1 0 4 0
>>>>           Sum: 5, Avg: 1, Min: 0, Max: 4, Diff: 4]
>>>>       [Scan RS (ms):  0.1  0.1  0.2  0.0
>>>>        Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.3]
>>>>       [Object Copy (ms):  0.7  0.7  0.6  0.5
>>>>        Min: 0.5, Avg: 0.6, Max: 0.7, Diff: 0.2, Sum: 2.5]
>>>>       [Termination (ms):  0.0  0.0  0.0  0.0
>>>>        Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
>>>>          [Termination Attempts : 1 1 1 1
>>>>           Sum: 4, Avg: 1, Min: 1, Max: 1, Diff: 0]
>>>>       [GC Worker Other (ms):  0.1  0.0  0.1  0.1
>>>>        Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.0, Sum: 0.2]
>>>>       [GC Worker Total (ms):  3.2  3.2  3.2  3.1
>>>>        Min: 3.1, Avg: 3.2, Max: 3.2, Diff: 0.1, Sum: 12.7]
>>>>       [GC Worker End (ms):  31101.4  31101.4  31101.4  31101.4
>>>>        Min: 31101.4, Avg: 31101.4, Max: 31101.4, Diff: 0.0, Sum: 
>>>> 124405.6]
>>>>    [Code Root Fixup: 0.0 ms]
>>>>    [Clear CT: 0.1 ms]
>>>>    [Cur Clear CC: 0.0 ms]
>>>>    [Cum Clear CC: 0.1 ms]
>>>>    [Min Clear CC: 0.0 ms]
>>>>    [Max Clear CC: 0.0 ms]
>>>>    [Avg Clear CC: 0.0 ms]
>>>>    [Other: 1.1 ms]
>>>>       [Choose CSet: 0.0 ms]
>>>>       [Ref Proc: 0.1 ms]
>>>>       [Ref Enq: 0.0 ms]
>>>>       [Free CSet: 0.6 ms]
>>>>    [Eden: 79.0M(79.0M)->0.0B(79.0M) Survivors: 1024.0K->1024.0K 
>>>> Heap: 80.2M(100.0M)->1261.0K(100.0M)]
>>>>  [Times: user=0.06 sys=0.00, real=0.04 secs]
>>>>
>>>>
>>>> Thanks,
>>>> Bengt
>>>
>>
>