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

Fri Jul 13 20:40:46 UTC 2012

On 2012-07-12 23:34, John Cuthbertson wrote:
> Hi Bengt,
>
> The latest webrev looks good to me.

Thanks, John!

Bengt

>
> 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/20120713/f48ee1a1/attachment.htm>