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
Fri Jun 29 12:37:47 UTC 2012
Hi John,
Thanks for taking such a close look at these changes!
Here is a full webrev based on your comments:
http://cr.openjdk.java.net/~brutisso/7178361/webrev.03
Here is just a diff of the changes I made based on your comments:
http://cr.openjdk.java.net/~brutisso/7178361/webrev.02-03-diff/
Thanks again for looking at this! Your comments were really good.
There are some responses inlined below.
Bengt
On 2012-06-29 02:25, John Cuthbertson wrote:
> Hi Bengt,
>
> Apologies for the delay in reviewing your changes. Note these comments
> from your first webrev and the line numbers are from applying your
> first patch to a clone of the hsx/hotspot-gc/hotspot repo at revision:
>
> changeset: 3417:1c280e5b8d31
> tag: tip
> user: amurillo
> date: Fri Jun 15 14:17:28 2012 -0700
> summary: 7175515: new hotspot build - hs24-b15
>
> Some of the comments are against code that you did not actually touch
> - you just touched near. But I think this a good opportunity for some
> cleanup
>
> Anyway onto the comments....
>
>
> g1GCPhaseTimes.hpp
> ------------------
> Would "max_gc_threads" be a better name for the parameter of the
> constructor?
Done.
>
> Also we might want to cache this so that we can re-initialize all
> per-worker thread slots in the time arrays at the start of each pause.
Done.
>
> See futher comments in g1CollectorPolicy.{ch}pp about possible other
> candidates for inclusion into this file.
>
> Line 102:
> Rename "start" to something like - note_gc_start(). "start" is too
> closely associated with threads IMO. Also should it also take the
> start time? That way the "end" routine
> could take an end time and do any necessary calculations.
Done.
>
> Line 103:
> Make "print" a private method and add a "note_gc_end" routine that
> calls print.
Done.
>
> g1GCPhaseTimes.cpp
> ------------------
> Line 27:
> Only include g1CollectedHeap.inline.hpp - that includes
> g1CollectedHeap.hpp.
Done.
>
> Line 97:
> The initialization of these values should be done in the
> "note_gc_start" routine. We want to detect if we don't record a value
> for one during the pause. So only
> initializing them once defeats that purpose.
Done.
>
> Line 119:
> Should sum_of be made static or even a [private] [static] member of
> the G1GCPhaseTime class?
sum_of() was actually not being used. I removed it instead.
>
> Line 166,167,...
> Argument formatting.
Done.
>
> Line 236:
> "accumulate_par_times" is a bit misnamed. "collapse_par_times",
> "average_par_times" might be better. Also I don't think you should be
> calling this directly from with
> G1CollectedHeap. It would be better to call this from a
> G1GCPhaseTimes::note_gc_end() type of routine, which is called by
> G1CollectorPolicy::record_collection_pause_end().
I renamed it to collapse_par_times(), but I still would like to call it
directly from G1CollectedHeap. The reason is that
record_collection_pause_end() need this to be called, but also the
note_gc_end() method. I don't like the note_gc_end() method to depend on
a call to record_collection_pause_end().
The clean solution would be to merge these two methods, but that's not
possible without changing the timing for the ergonomics, which is
exactly what I am trying to avoid.
>
> Line 246:
> Perhaps find a better place for this. Or even add a new routine:
> calculate_known_time()?
It turns out that we always set _cur_collection_par_time_ms even for
ParallelGCThreads=0. And where we use accounted_time_ms() we are really
just interested in deducting the parallel time of the pause from the
total time of the pause. It should be fine to use
_cur_collection_par_time_ms for this.
The only place where we actually care about the _known_time is in
TraceGen0TimeData::record_end_collection() where we try to figure out
the difference between _cur_collection_par_time_ms and the known
parallel time. So, I inlined the _known_time calculation in
TraceGen0TimeData::record_end_collection().
>
> Line 315:
> We should probably move this out of the "print" routine - perhaps into
> the "note_gc_end" type of routine. Then "print" just prints.
Done.
>
> g1CollectorPolicy.hpp
> ---------------------
> Line 65-66:
> Why did you remove the indentation levels? IMO they are easier to work
> with than explicitly listing spaces.
Two reasons. One technical. I moved LineBuffer (that handled the
indentation) into g1GCPhaseTime.cpp and I didn't really want to expose
it outside of that module. The other, more design related question, is
whether the TraceGen0Time output should really use the same formatting
as the PrintGCDetails formatting. As it was it was not doing a good job
with the indentations. It was also pretty difficult to read the code and
guess how many white spaces would end up where. With the white spaces
explicitly in the print statements it got clearer what really happened
and I could fix the indentation issues.
I'm sure we can introduce some indentation abstraction for TraceGen0Time
too, but since I didn't really like the way it was and I had to move the
LineBuffer I thought it was easiest to revert back to using explicit
space characters in the print statements.
>
> Line 178:
> Why didn't you include _cur_collection_pause_used_at_start_bytes or
> why did you include _curr_collection_pause_used_regions_at_start? Should
> either be included? Including non-time based fields makes
> G1GCPhaseTimes a bit of a misnomer.
My bad. At one point I was trying out G1GCPhaseTimes as G1GCPhaseData
and moved a lot more stuff in there. Then I decided against that idea
and moved everything out again. But I must have missed
_curr_collection_pause_used_regions_at_start. Thanks for finding it! I
moved it out now.
>
> Can we rename _cur_collection_pause_used_regions_at_start to
> _cur_collection_pause_used_at_start_regions? That way the "units" of
> the variable are at the end?
Personally I find the name _cur_collection_pause_used_at_start_regions
strange. I prefer _cur_collection_pause_used_regions_at_start. Since it
is not really related to my change (anymore) I will leave it untouched now.
>
> Line 660:
> The accessor name is ugly - perhaps just use "phase_times"?
Done.
>
> Line 675-680:
> Should:
>
> double _cur_mark_stop_world_time_ms;
> double _mark_remark_start_sec;
> double _mark_cleanup_start_sec;
>
> also be included in the phase times class?
I think not. The way I look at it G1GCPhaseTimes should only include
timing data for a normal G1 GC. We could definitely wrap the other
timing data in other classes, but I think it is good if we keep the
focus of this class simple.
>
> Line 787:
> I would not remove record_concurrent_pause_end(). I would leave it in
> case we ever want to record anything at the end of a concurrent pause.
> Perhaps these routines should also be moved to the GC phase times class.
I disagree. I think we can easily add it back in if we need it. No point
in keeping empty methods around.
>
> Line 789:
> Does it make more sense to have record_collection_pause_start() take
> the starting time and number of GC threads and have it record the
> start time in the G1 phase times object. Then
> record_collection_pause_end() can take the "end" time - also pass it
> to the phase times object and have the phase times object do the
> calculations (see earlier
> comments about g1GCPhaseTimes.hpp).
I already did that based on your earlier comments ;-)
>
> g1CollectorPolicy.cpp
> ---------------------
> Line 199-204:
> Should the calculation of index use _parallel_gc_threads?
Good idea! That simplified the code to a one-liner.
>
> Line 748:
> Perhaps G1GCPhaseTimes should have note_full_gc_start(),
> note_inc_gc_start(), and corresponding end routines. The
> "note_[full_]gc_start() routines would then be used
> to set the _cur_collection_start_sec.
Again, I would like to keep G1GCPhaseTimes to only handle normal GCs.
Otherwise I'm afraid the class will grow too big. I had not realized
that full GCs used the same _cur_collection_start_sec field to keep
track of its time.
I separated the full GC timing out to a
G1CollectorPolicy::_full_collection_start_sec variable. That way we
won't risk mixing full GC and normal GC timing data.
>
> Line 905:
> See earlier comments about re-initializing/clearing the _par_last_gc
> arrays.
>
> Line 1145:
> See earlier comments about record_collection_pause_end().
I was not really able to figure out what the two line numbers above
referred to, but since both comments refer to earlier comments I hope
that I have fixed it. :-)
>
> Line 2155:
> Old code with the levels looks much nicer - IMO.
See my earlier comment on this.
>
> g1RemSet.cpp
> ------------
> To make this consistent - perhaps change this code to call
> os::elapsedTime() again (rather than in
> G1GCPhaseTimes::record_cc_clear_time()) and pass the elapsed time delta.
I don't really understand this comment. Can you explain a bit more what
you mean?
>
> Other than these, it looks OK.
Great!
>
> Again - sorry for the delay in getting back to you.
No problem. Thanks for looking at this!
>
> JohnC
>
>
> On 06/28/12 02:35, Bengt Rutisson 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
>>> <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/20120629/e2de862b/attachment.htm>
More information about the hotspot-gc-dev
mailing list