RFR (M): 8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases

[Bengt Rutisson]

Hi again,

Here is an updated webrev:
http://cr.openjdk.java.net/~brutisso/8074037/webrev.01/

And here's the diff compared to the last webrev:
http://cr.openjdk.java.net/~brutisso/8074037/webrev.00-01.diff/

I tried to clean up the seconds vs. milliseconds confusion by making it 
G1GCPhaseTimes' responsibility to handle the conversion in all cases. 
So, the interface is now that times are reported in seconds (for example 
G1GCPhaseTimes::record_time_secs()) but returned in milliseconds (for 
example G1GCPhaseTimes::average_time_ms()). I suffixed the method names 
"_secs" and "_ms" to make it easier to follow the code.

I'm not very happy about this inconsistency, but I want it to be an 
intermediate step on the way to getting rid of os::elapsedTime() completely.

StefanK also suggested to move the logging code out to its own class. 
This simplified the logging quite a bit I think. The class, 
G1GCPhasePrinter, has to know a lot about both G1GCPhaseTimes and 
WorkerDataArray, but I still think it is nice to have the logging 
separated out.

I didn't read Thomas' email with comments until after I had prepared 
this updated webrev. But I think I have addressed the issues brought up 
there. Thanks for looking at this, Thomas!

Bengt

On 2015-03-02 09:23, Bengt Rutisson wrote:
>
> Hi Kim,
>
> Thanks for looking at this!
>
> On 2015-02-28 00:43, Kim Barrett wrote:
>> On Feb 27, 2015, at 10:38 AM, Bengt Rutisson 
>> <bengt.rutisson at oracle.com> wrote:
>>> Can I have a couple of reviews for this cleanup change?
>>>
>>> http://cr.openjdk.java.net/~brutisso/8074037/webrev.00/
>>> https://bugs.openjdk.java.net/browse/JDK-8074037
>>>
>>> […]
>>> The patch also introduces a new class called G1GCPhaseTimesTracker, 
>>> which is a scoped object to simplify time measurements. I've also 
>>> tried to move conversion of times down to when we print the log 
>>> messages instead of when we store them. This removes several "* 
>>> 1000.0" in the code. Eventually I would like to replace 
>>> os::elapsedTime() with os::elapsed_counter(). But that should be 
>>> done as a separate patch.
>> Before I proceed any further with this review, I feel like I'm getting
>> lost in unit changes. In some places values of msecs used to be used
>> but now we're using secs, right? But it seems like there might be some
>> confusion about that, and I'm not sure whether it's me or the code
>> that's confused.
>>
>> For example:
>>
>> src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp
>> 1079       cost_per_card_ms = 
>> phase_times()->average_time(G1GCPhaseTimes::UpdateRS) / (double) 
>> _pending_cards;
>> 1080       _cost_per_card_ms_seq->add(cost_per_card_ms);
>>
>> I think the values that have been recorded in the phase_times are
>> secs, and average_time appears to just use the values as is.  So
>> shouldn't that now be cost_per_card_secs?  And the value added to
>> _cost_per_card_ms_seq needs to be cost_per_card_secs * 1000.0?
>
> Right! Good catch! I was so happy to get rid of some of the "* 1000.0" 
> statements sprinkled all over the G1 code that I forgot to add some of 
> them back ;)
>
> I'll send out an updated webrev soon.
>
> Bengt
>
>>
>> Oh how I wish for a units package!
>>
>