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

[Bengt Rutisson]

Hi all,

After some testing I noticed that I had done all my testing with 
StringDedup enabled. The code did not work properly with it disabled 
since StringDedup reported times for full GCs and concurrent marking 
even though it was not logged anywhere. I changed the code to only 
report times when the times will be reported as part of a GC.

Here's an updated webrev:
http://cr.openjdk.java.net/~brutisso/8074037/webrev.02/

And a diff compared to the last review:
http://cr.openjdk.java.net/~brutisso/8074037/webrev.01-02.diff/

Thanks,
Bengt

On 2015-03-02 17:15, Bengt Rutisson wrote:
>
> 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!
>>>
>>
>