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

Thu Jun 28 13:32:10 UTC 2012

Yes, Mikael is quite right - c++ only places restriction on the index that
it be within array bounds, signedness doesn't matter.

I guess the "proper" thing here would be to use size_t to index the array,
but since uint will be more than enough, I don't think it matters.  One can
also typedef a type as "worker_i" and use that.

Cheers,

Vitaly

Sent from my phone
On Jun 28, 2012 5:37 AM, "Bengt Rutisson" <bengt.rutisson at oracle.com> wrote:

> **
>
> Hi again,
>
> Here is an updated webrev:
> http://cr.openjdk.java.net/~brutisso/7178361/webrev.02/
>
> It includes the assert to check that we are set up active_workers to be
> less than ParallelGCThreads that Vitaly suggested.
>
> Also, I will have to change my earlier statement about using signed values
> to index C++ arrays. It is fine with unsigned values too (thanks Mikael
> Vidstedt for making me reconsider this statement). So, Vitaly, I went ahead
> and implemented your first suggestion to use uint for the worker indexes.
>
> Thanks again for the review Vitaly. I know John Cuthbertson is looking at
> this too.
>
> Benbgt
>
>
> On 2012-06-25 16:23, Vitaly Davidovich wrote:
>
> 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/20120628/4cfc08c3/attachment.htm>