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

[John Cuthbertson]

Hi Bengt,

The latest webrev looks good to me.

JohnC

On 07/11/12 13:58, Bengt Rutisson wrote:
>
> 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/20120712/92d55d98/attachment.htm>