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

Bengt Rutisson bengt.rutisson at oracle.com
Wed Mar 4 15:04:34 UTC 2015

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:

And here's the diff compared to the last one:


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!

More information about the hotspot-gc-dev mailing list