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

[Bengt Rutisson]

Hi again,

Yet another update to this webrev. I realized that I can move the 
WorkerDataArray class from the hpp file to the cpp file. I think that's 
worth doing to show that it is just in internal class.

Also, I renamed the GCPhase* enums and variables to GCParPhase* to make 
it possible to use the GCPhase* names for a possible future extension to 
store the "single time phases" in something similar to the _gc_phases array.

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

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

Thanks,
Bengt


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