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

[Bengt Rutisson]

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
>