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

[Bengt Rutisson]

Thanks Jesper and John! All set to pus this now.

Bengt

On 2012-05-14 13:54, Jesper Wilhelmsson wrote:
> Looks good. Ship it!
> /Jesper
>
> On 2012-05-14 13:32, Bengt Rutisson wrote:
>>
>> 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
>>>>>
>>>>
>>>
>>