Request for review (M): 7172279: G1: Clean up TraceGen0Time and TraceGen1Time data gathering
Mikael Vidstedt
mikael.vidstedt at oracle.com
Tue May 29 21:56:43 UTC 2012
On 2012-05-29 13:32, Bengt Rutisson wrote:
> On 2012-05-29 19:47, Mikael Vidstedt wrote:
>>
>> On 2012-05-28 23:58, Bengt Rutisson wrote:
>>>
>>> Hi again,
>>>
>>> I should also have mentioned that this change should not alter the
>>> log output. (Except for the ParallelGCThreads = 0 case which now
>>> will look the same as PrallelGCThreads >= 1 case.)
>>
>> +1 for not changing the log output in a minor/update release. What
>> does the "except" part mean?
>
> Good question. It is more or less just a matter of indentation. See
> the examples below.
>
> There are two single threaded cases. One with ParallelGCThreads = 0
> and one with ParallelGCThreads = 1. My change make their output the
> same. Basically the ParallelGCThreads = 1 assumes a parallel state so
> we indent the different phases under a "Parallel" overall time, and we
> add a "Termination" phase which will be 0 for single threaded execution.
>
> By default we use parallel excution. The ParallelGCThreads = 0 is more
> or less a debug tool to help eliminate thread issues. It is not worth
> treating specially in the code and it is unlikely that it is being
> used by customers.
>
> Also, this is a pure G1 change and the output is only printed once
> during a complete run (when we exit the vm). There is no risk of
> breaking any customer parsers with this change.
>
> The examples below are from before my change. After my change both
> will look like the -XX:ParallelGCThreads=1 example.
Thanks for the detailed response. This does indeed look like a great
consistency improvement!
Cheers,
Mikael
>
> Bengt
>
>
> -XX:ParallelGCThreads=0
>
>
> ALL PAUSES
> Total = 0.54 s (avg = 41.46 ms)
> (num = 13, std dev = 40.28 ms, max = 146.02 ms)
>
>
> Young GC Pauses: 13
> Mixed GC Pauses: 0
>
> EVACUATION PAUSES
> Evacuation Pauses = 0.54 s (avg = 41.46 ms)
> (num = 13, std dev = 40.28 ms, max = 146.02 ms)
> Root Region Scan Wait = 0.00 s (avg = 0.00 ms)
> Ext Root Scanning = 0.04 s (avg = 3.28 ms)
> SATB Filtering = 0.00 s (avg = 0.00 ms)
> Update RS = 0.02 s (avg = 1.80 ms)
> Scan RS = 0.04 s (avg = 3.14 ms)
> Object Copy = 0.42 s (avg = 32.04 ms)
> Mark Closure = 0.00 s (avg = 0.00 ms)
> Clear CT = 0.00 s (avg = 0.04 ms)
> Other = 0.02 s (avg = 1.16 ms)
>
> MISC
> Stop World = 0.00 s (avg = 0.33 ms)
> (num = 13, std dev = 0.04 ms, max = 0.41 ms)
> Yields = 0.00 s (avg = 0.00 ms)
> (num = 0, std dev = 0.00 ms, max = 0.00 ms)
>
> 2 full_gcs: total time = 0.06 s (avg = 28.65ms).
> [std. dev = 11.57 ms, max = 40.22 ms]
>
>
>
>
>
>
> -XX:ParallelGCThreads=1
>
>
> ALL PAUSES
> Total = 0.56 s (avg = 47.03 ms)
> (num = 12, std dev = 45.22 ms, max = 159.05 ms)
>
>
> Young GC Pauses: 12
> Mixed GC Pauses: 0
>
> EVACUATION PAUSES
> Evacuation Pauses = 0.56 s (avg = 47.03 ms)
> (num = 12, std dev = 45.22 ms, max = 159.05 ms)
> Root Region Scan Wait = 0.00 s (avg = 0.00 ms)
> Parallel Time = 0.55 s (avg = 45.83 ms)
> Ext Root Scanning = 0.04 s (avg = 3.74 ms)
> SATB Filtering = 0.00 s (avg = 0.00 ms)
> Update RS = 0.02 s (avg = 1.95 ms)
> Scan RS = 0.03 s (avg = 2.73 ms)
> Object Copy = 0.45 s (avg = 37.17 ms)
> Termination = 0.00 s (avg = 0.00 ms)
> Parallel Other = 0.00 s (avg = 0.25 ms)
> Mark Closure = 0.00 s (avg = 0.00 ms)
> Clear CT = 0.00 s (avg = 0.06 ms)
> Other = 0.01 s (avg = 1.14 ms)
>
> MISC
> Stop World = 0.00 s (avg = 0.33 ms)
> (num = 12, std dev = 0.04 ms, max = 0.44 ms)
> Yields = 0.00 s (avg = 0.00 ms)
> (num = 0, std dev = 0.00 ms, max = 0.00 ms)
>
> 2 full_gcs: total time = 0.06 s (avg = 29.65ms).
> [std. dev = 12.58 ms, max = 42.22 ms]
>
>
>
>
>
>
>>
>> Thanks,
>> Mikael
>>
>>>
>>> I tested this by leaving the old code in and comparing the output
>>> from the old code with the new code. In my tests they look exactly
>>> the same.
>>>
>>> Bengt
>>>
>>> On 2012-05-28 22:37, Bengt Rutisson wrote:
>>>>
>>>> Hi all,
>>>>
>>>> Can I have a couple of code reviews for this change?
>>>> http://cr.openjdk.java.net/~brutisso/7172279/webrev.01/
>>>>
>>>> Background
>>>> I am preparing a change to remove the special treatment of the
>>>> single threaded case for G1 PrintGCDetails output. We should be
>>>> able to use the same code for both ParallelGCThreads = 0 and
>>>> PrallelGCThreads >= 1. This will hopefully simplify the logging code.
>>>>
>>>> In preparation for that change I would like to clean up the
>>>> TraceGen0Time and TraceGen1Time data gathering code a bit. It is
>>>> currently kind of difficult to follow the code and there is no
>>>> clear distinction between the data gathered for these two cases
>>>> compared to the data gathered for PrintGCDetails output.
>>>>
>>>> Here is what I tried to do:
>>>>
>>>> - Remove the unnecessary define_num_seq macro and the multiple
>>>> inheritance of the Summary class.
>>>> - Replaced the above with two classes, TraceGen0TimeData and
>>>> TraceGen1TimeData, that will encapsulate the data needed.
>>>> - Made sure that the data is only updated if the corresponding
>>>> flags are turned on.
>>>> - Removed the separate "non-parallel" case. All data is available
>>>> even with ParallelGCThreads = 0.
>>>> - Removed the ExitAfterGCNum flag. I hardly think this is an
>>>> appropriate product flag to have in the code.
>>>> - Removed some unused methods.
>>>> - Removed 7 year old assert(true) with accompanying comments.
>>>> - Removed the unused aux time concept.
>>>>
>>>> There was one thing that I was hesitant to remove, but finally
>>>> decided to remove anyway. It was the
>>>> G1CollectorPolicy::check_other_times() method. First I added the
>>>> same method to TraceGen0TimeData. But it is a lot of code and I am
>>>> not sure it is very useful. It can't do any exact checks and it
>>>> seems unlikely to me that it will detect any issues. Also, it seems
>>>> to me like the code was in the wrong place. I would have preferred
>>>> it in some kind of verify method rather than in a print method.
>>>>
>>>> Thanks,
>>>> Bengt
>>>
>>
>
More information about the hotspot-gc-dev
mailing list