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

[Bengt Rutisson]

Hi John,

Thanks a lot for looking at this! Good comments as always!

I applied your latest comments. (Good catch about the initialization of 
the card cleaning timing variables.)

Here is an updated webrev:
http://cr.openjdk.java.net/~brutisso/7178361/webrev-04/

For convenience, here is a webrev with just the latest changes that I 
applied based on your two last emails:
http://cr.openjdk.java.net/~brutisso/7178361/webrev-03-04-diff/

I'm getting back to work next week and I'd like to start on the next 
step (to clean up the single threaded logging) based on this change. So, 
I'd like to get this pushed before Monday.

If I don't get any objections before tomorrow I'll push this. I can 
always include some changes in my next push as well if there is late 
feedback.

Thanks again for the review!
Bengt

On 2012-07-04 00:07, John Cuthbertson wrote:
> Hi Bengt,
>
> Finished looking at the rest of the webrev. Replies are inline.....
>
> On 06/29/12 05:37, Bengt Rutisson wrote:
>>>
>>> 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.
>
> Thanks again - I can see you even extended the idea to include other 
> cachable items from the start of the pause. It also looks good.
>
>
>>> 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.
>
> OK. I was expecting note_gc_end() to be called by 
> record_collection_pause_end() but I see your point  - they are kind of 
> inter-dependent.  I'm OK with the current solution. I agree that it's 
> good not to change the timer for the ergonomics - it covers the part 
> of the GC we can control and make changes to.
>
>>>
>>> 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.
>
> I think we'll agree to disagree with this one - but I don't feel that 
> strongly so let's go with your current solution.
>
> I'm OK with your replies to the remaining comments.
>
> Based upon the latest patch, however, I think you need the following 
> initializers:
>
>     _min_clear_cc_time_ms(-1.0),
>     _max_clear_cc_time_ms(-1.0),
>     _cur_clear_cc_time_ms(0.0),
>     _cum_clear_cc_time_ms(0.0),
>     _num_cc_clears(0L),
>
> in the G1GCPhaseTimes constructor - otherwise the min, max, and 
> cumulative card count times end up invalid:
>
>    [Cur Clear CC: 0.0 ms]
>    [Cum Clear CC: 
> -7478635795308384178678626234477338765623121979189748343809653167004330313976030486954447383286129802186779679841804100646674790742262819242223986790247088643994984488195310211210345403332642667378471000230265516264857328262241129957569855488.0 
> ms]
>    [Min Clear CC: 0.0 ms]
>    [Max Clear CC: 0.0 ms]
>
> Also, since the previous version of the finest log-level didn't 
> display these items, perhaps only display them if Verbose is also 
> enabled? In most cases card cache count clearing  will exhibit itself 
> as a higher HC Worker Other time for worker 0.
>
> Everything else looks OK.
>
> Thanks,
>
> JohnC


-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20120711/866bd8ad/attachment.htm>