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
Mon Jun 25 13:27:27 UTC 2012
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 Snippet 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/20120625/3559a9ac/attachment.htm>
More information about the hotspot-gc-dev
mailing list