Request for review (M): 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
Bengt Rutisson
bengt.rutisson at oracle.com
Thu Jun 28 09:35:42 UTC 2012
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
> <mailto: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 <mailto:bengt.rutisson at oracle.com>> wrote:
>>
>>
>> Hi again,
>>
>> Updated webrev:
>> http://cr.openjdk.java.net/~brutisso/7178361/webrev.01/
>> <http://cr.openjdk.java.net/%7Ebrutisso/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/
>> <http://cr.openjdk.java.net/%7Ebrutisso/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/
>> <http://cr.openjdk.java.net/%7Ebrutisso/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/82dd391f/attachment.htm>
More information about the hotspot-gc-dev
mailing list