Request for review (M): 7172279: G1: Clean up TraceGen0Time and TraceGen1Time data gathering
Bengt Rutisson
bengt.rutisson at oracle.com
Tue May 29 20:32:02 UTC 2012
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.
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