Request for review (M): 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause

[Vitaly Davidovich]

Thanks for the explanation Bengt - all good from me, FWIW :).

Sent from my phone
On Jun 25, 2012 9:24 AM, "Bengt Rutisson" <bengt.rutisson at oracle.com> wrote:

>
> Hi Vitaly,
>
> On 2012-06-21 14:36, Vitaly Davidovich wrote:
>
> Hi Bengt,
>
>  Looks good.  One question: the asserts you added check against
> _active_gc_threads, but the arrays are sized with parallel_gc_threads.  The
> assumption then is that active_gc_threads <= parallel_gc_threads? If so,
> maybe assert that piece as well.
>
>
> I see your point. Currently _active_gc_threads is set up to be the same as
> parallel_gc_threads, but I can add an assert to that effect in the
> constructor of G1GCPhaseTimes.
>
>  Also, maybe consider moving the range asserts into a macro or helper
> function so that you don't have to repeat the exact same 2 lines?
>
>
> Somehow I find the inlined asserts more readable. I'll think about it.
> Thanks for the suggestion.
>
>
>  Finally (forgot to mention this in my initial email), a minor point --
> should the sentinel -1234.0 value that you set the arrays to be defined as
> a constant so if you, for some reason, decide to change it, you just update
> 1 place? Very minor though :).
>
>
> Yes, this should be fixed. However, I just moved this code from one place
> to anther and I plan on revisiting this code and cleaning it up a bit with
> my next change. That change should remove the serial special case in this
> code. Is it ok if I leave this cleanup for that change?
>
>
>  As for worker_i being unsigned, I was thinking the method would take
> unsigned which perhaps better expresses the range/intent of the value, but
> can cast internally to signed to do array lookup.  Anyhow, not a big deal
> and what you have is fine, obviously.
>
>
> Yes, I tend to agree, but I think I'll leave them as int for now. Maybe
> I'll change this too as part of my next cleanup.
>
>  The output looks nice with your changes -- I wonder though if even
> whitespace changes are deemed too risky in terms of possibly breaking
> client parsers (would have to be fairly brittle ones, but nonetheless).
>
>
> Right. However, it looks to me like this output has been changing its
> indentation levels over time, so if any parsers break due to white space
> changes they are probably already broken ;-)
>
> Thanks again for looking at this!
> Bengt
>
>
>  Thanks,
>
>  Vitaly
>
> On Thu, Jun 21, 2012 at 7:54 AM, Bengt Rutisson <bengt.rutisson at oracle.com
> > wrote:
>
>>
>> Hi again,
>>
>> Updated webrev:
>> http://cr.openjdk.java.net/~brutisso/7178361/webrev.01/
>>
>> I added some asserts as suggested by Vitaly and I did some white space
>> changes to the TraceGen0Time logging. I hope this will not break any
>> parsers. It is just intended to align the output up a bit better to be more
>> readable.
>>
>> Here is a webrev with just the change I made compared to my previous
>> webrev:
>> http://cr.openjdk.java.net/~brutisso/7178361/webrev.00-01-diff/
>>
>> Here is an example of what the TraceGen0Time output looks like after my
>> change:
>>
>> ALL PAUSES
>>   Total                    =     0.95 s (avg =    63.44 ms)
>>                                         (num =    15, std dev =    47.84
>> ms, max =   150.30 ms)
>>
>>
>>   Young GC Pauses:       14
>>   Mixed GC Pauses:        1
>>
>> EVACUATION PAUSES
>>   Evacuation Pauses        =     0.95 s (avg =    63.44 ms)
>>                                         (num =    15, std dev =    47.84
>> ms, max =   150.30 ms)
>>      Root Region Scan Wait =     0.00 s (avg =     0.00 ms)
>>      Parallel Time         =     0.94 s (avg =    62.39 ms)
>>         Ext Root Scanning  =     0.11 s (avg =     7.22 ms)
>>         SATB Filtering     =     0.00 s (avg =     0.00 ms)
>>         Update RS          =     0.04 s (avg =     2.81 ms)
>>         Scan RS            =     0.03 s (avg =     2.07 ms)
>>         Object Copy        =     0.75 s (avg =    49.75 ms)
>>         Termination        =     0.00 s (avg =     0.02 ms)
>>         Parallel Other     =     0.01 s (avg =     0.51 ms)
>>      Clear CT              =     0.00 s (avg =     0.09 ms)
>>      Other                 =     0.01 s (avg =     0.90 ms)
>>
>> MISC
>>   Stop World               =     0.01 s (avg =     0.48 ms)
>>                                         (num =    15, std dev =     0.19
>> ms, max =     0.79 ms)
>>   Yields                   =     0.00 s (avg =     0.27 ms)
>>                                         (num =     2, std dev =     0.05
>> ms, max =     0.32 ms)
>>
>> Thanks,
>> Bengt
>>
>>
>>
>> On 2012-06-20 15:15, Bengt Rutisson wrote:
>>
>>>
>>> Hi everyone,
>>>
>>> Could I please have some reviews for this change:
>>> http://cr.openjdk.java.net/~brutisso/7178361/webrev.00/
>>>
>>> Background
>>> As part of the PrintGC and PrintGCDetails logging there is information
>>> about how long the GC pause was. The timing of the pause was done
>>> differently in G1 depending on whether PrintGC or PrintGCDetails were
>>> enabled. It turns out that PrintGCDetails was just timing part of the pause.
>>>
>>> This change will make both PrintGC and PrintGCDetails use the same
>>> timing. To achieve this I had to refactor the code a bit. I moved all the
>>> timing data out of G1CollectorPolicy into a new class called G1GCPhaseTimes.
>>>
>>> My intention is that this change should not alter the format of the
>>> output of PrintGC or PrintGCDetails. It should just correct the timing data.
>>>
>>> However, I did find that we are collecting timing information about card
>>> counts, under an #ifdef. I moved this to the finest log level instead. This
>>> does not change the existing format for normal usage of PrintGC or
>>> PrintGCDetails.
>>>
>>> Also, I had to update how the TraceGen0Time data is logged. I will have
>>> another look at this, but my idea was to leave the format exactly as it
>>> was. However, I think the format has decayed over time so maybe I'll try to
>>> clean it up.
>>>
>>> I intend to follow this change up with a change to remove the special
>>> treatment of the single threaded case for PrintGCDetails (tracked in CR
>>> 7178363).
>>>
>>> Finally, this work revealed an issue with how the ergonomics in G1
>>> measure the collection pauses. I did not want to change this behavior now
>>> so I filed a separate RFE for that (7178365: G1: Ergonomics only count part
>>> of the collection pause).
>>>
>>> Bengt
>>>
>>
>>
>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20120625/84094423/attachment.htm>