RFR: JDK-8150068: Log the main G1 phases at info level
Bengt Rutisson
bengt.rutisson at oracle.com
Fri Feb 26 14:15:39 UTC 2016
Here's an updated webrev that is based on top of Thomas recent changes
for JDK-8150630, JDK-8076463, JDK-8150629 and JDK-8140777:
http://cr.openjdk.java.net/~brutisso/8150068/webrev.02/
I had to do some manual merging so unfortunately it is not easy to
provide a diff compared to the last version. All merging was in
g1GCPhaseTimes.cpp and they were due to the addition of PreserveCMReferents.
Thanks,
Bengt
On 2016-02-26 12:48, Bengt Rutisson wrote:
>
> Hi again,
>
> Stefan J did an offline code review of this change and we've updated
> the patch based on his comments.
>
> Here's an updated webrev:
> http://cr.openjdk.java.net/~brutisso/8150068/webrev.01/
>
> Here's a diff compared to the last version:
> http://cr.openjdk.java.net/~brutisso/8150068/webrev.00-01.diff/
>
> The main changes is to try to get rid of some code duplication in
> G1GCPhaseTimes by using more templates, macros and moving some
> printing code to WorkerDataArray.
>
> Also the test was updated to also check that the log messages are
> logged at the correct level.
>
> Thanks,
> Bengt
>
> On 2016-02-17 17:00, Bengt Rutisson wrote:
>>
>> Hi everyone,
>>
>> Could I have a couple of reviews for this change?
>>
>> http://cr.openjdk.java.net/~brutisso/8150068/webrev.00/
>> https://bugs.openjdk.java.net/browse/JDK-8150068
>>
>> The current G1 logging logs the phases at debug level. This means
>> that running with -Xlog:gc*, which is supposed to be similar to the
>> old PrintGCDetails, does not log the phases.
>>
>> It is necessary to add gc+phases=debug to get similar logging to the
>> old logging. However, doing that gives more logging that the old
>> logging.
>>
>> We should split the phase logging up so that the hight level phases
>> are logged at info level and thus are logged with -Xlog:gc* and that
>> the rest of the phases are divided up between debug and trace in a
>> sensible way.
>>
>> With the proposed change running with -Xlog:gc* looks like this:
>>
>> [0,685s][info][gc,start ] GC(5) Pause Young (G1 Evacuation Pause)
>> (0,685s)
>> [0,701s][info][gc,phases ] GC(5) Evacuate Collection Set: 5,8ms
>> [0,702s][info][gc,phases ] GC(5) Code Roots: 0,0ms
>> [0,702s][info][gc,phases ] GC(5) Clear Card Table: 0,0ms
>> [0,702s][info][gc,phases ] GC(5) Expand Heap After Collection: 0,2ms
>> [0,702s][info][gc,phases ] GC(5) Free Collection Set: 6,9ms
>> [0,702s][info][gc,phases ] GC(5) Other: 3,1ms
>> [0,702s][info][gc,heap ] GC(5) Eden regions: 29->0(29)
>> [0,702s][info][gc,heap ] GC(5) Survivor regions: 3->3(4)
>> [0,702s][info][gc,heap ] GC(5) Old regions: 59->59
>> [0,702s][info][gc,heap ] GC(5) Humongous regions: 0->0
>> [0,702s][info][gc,metaspace] GC(5) Metaspace: 2975K->2975K(1056768K)
>> [0,703s][info][gc ] GC(5) Pause Young (G1 Evacuation Pause)
>> 89M->61M(506M) (0,685s, 0,703s) 17,704ms
>> [0,703s][info][gc,cpu ] GC(5) User=0,10s Sys=0,00s Real=0,02s
>>
>>
>> Running with -Xlog:gc*,gc+phases=debug looks like this:
>>
>> [0,668s][info ][gc,start ] GC(5) Pause Young (G1 Evacuation Pause)
>> (0,668s)
>> [0,680s][info ][gc,phases ] GC(5) Evacuate Collection Set: 4,3ms
>> [0,680s][debug][gc,phases ] GC(5) Ext Root Scanning (ms): Min:
>> 0,0, Avg: 0,2, Max: 0,3, Diff: 0,3, Sum: 5,3
>> [0,680s][debug][gc,phases ] GC(5) Update RS (ms): Min: 0,2,
>> Avg: 0,6, Max: 3,9, Diff: 3,7, Sum: 12,8
>> [0,680s][debug][gc,phases ] GC(5) Processed Buffers: Min: 0,
>> Avg: 1,1, Max: 4, Diff: 4, Sum: 25
>> [0,680s][debug][gc,phases ] GC(5) Scan RS (ms): Min: 0,0,
>> Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,2
>> [0,680s][debug][gc,phases ] GC(5) Code Root Scanning (ms):
>> Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
>> [0,680s][debug][gc,phases ] GC(5) Object Copy (ms): Min: 0,0,
>> Avg: 3,0, Max: 3,5, Diff: 3,5, Sum: 70,0
>> [0,680s][debug][gc,phases ] GC(5) Termination (ms): Min: 0,0,
>> Avg: 0,1, Max: 0,2, Diff: 0,2, Sum: 3,4
>> [0,680s][debug][gc,phases ] GC(5) Termination Attempts: Min:
>> 1, Avg: 1,0, Max: 1, Diff: 0, Sum: 23
>> [0,680s][debug][gc,phases ] GC(5) GC Worker Other (ms): Min:
>> 0,0, Avg: 0,2, Max: 3,6, Diff: 3,6, Sum: 3,8
>> [0,680s][debug][gc,phases ] GC(5) GC Worker Total (ms): Min:
>> 3,9, Avg: 4,2, Max: 4,2, Diff: 0,4, Sum: 95,5
>> [0,680s][info ][gc,phases ] GC(5) Code Roots: 0,0ms
>> [0,680s][debug][gc,phases ] GC(5) Code Roots Fixup: 0,0ms
>> [0,680s][debug][gc,phases ] GC(5) Code Roots Purge: 0,0ms
>> [0,680s][info ][gc,phases ] GC(5) Clear Card Table: 0,1ms
>> [0,680s][info ][gc,phases ] GC(5) Expand Heap After Collection:
>> 0,2ms
>> [0,680s][info ][gc,phases ] GC(5) Free Collection Set: 6,4ms
>> [0,680s][debug][gc,phases ] GC(5) Young Free Collection Set: 6,4ms
>> [0,680s][debug][gc,phases ] GC(5) Non-Young Free Collection
>> Set: 0,0ms
>> [0,680s][info ][gc,phases ] GC(5) Other: 0,9ms
>> [0,680s][debug][gc,phases ] GC(5) Choose CSet: 0,0ms
>> [0,680s][debug][gc,phases ] GC(5) Ref Proc: 0,2ms
>> [0,680s][debug][gc,phases ] GC(5) Ref Enq: 0,0ms
>> [0,680s][debug][gc,phases ] GC(5) Redirty Cards: 0,0ms
>> [0,680s][debug][gc,phases ] GC(5) Humongous Register: 0,0ms
>> [0,680s][debug][gc,phases ] GC(5) Humongous Reclaim: 0,0ms
>> [0,680s][info ][gc,heap ] GC(5) Eden regions: 29->0(29)
>> [0,680s][info ][gc,heap ] GC(5) Survivor regions: 3->3(4)
>> [0,680s][info ][gc,heap ] GC(5) Old regions: 59->59
>> [0,681s][info ][gc,heap ] GC(5) Humongous regions: 0->0
>> [0,681s][info ][gc,metaspace] GC(5) Metaspace: 2975K->2975K(1056768K)
>> [0,681s][info ][gc ] GC(5) Pause Young (G1 Evacuation Pause)
>> 89M->61M(506M) (0,668s, 0,681s) 12,669ms
>> [0,681s][info ][gc,cpu ] GC(5) User=0,09s Sys=0,00s Real=0,01s
>>
>>
>> Running with -Xlog:gc*,gc+phases=trace looks like this:
>>
>> [0,668s][info ][gc,start ] GC(5) Pause Young (G1 Evacuation Pause)
>> (0,668s)
>> [0,680s][info ][gc,phases ] GC(5) Evacuate Collection Set: 4,3ms
>> [0,680s][trace][gc,phases ] GC(5) GC Worker Start (ms): Min:
>> 668,3, Avg: 668,4, Max: 668,7, Diff: 0,4
>> [0,680s][debug][gc,phases ] GC(5) Ext Root Scanning (ms): Min:
>> 0,0, Avg: 0,2, Max: 0,3, Diff: 0,3, Sum: 5,3
>> [0,680s][trace][gc,phases ] GC(5) Thread Roots (ms): Min:
>> 0,0, Avg: 0,0, Max: 0,1, Diff: 0,1, Sum: 0,3
>> [0,680s][trace][gc,phases ] GC(5) StringTable Roots (ms):
>> Min: 0,0, Avg: 0,2, Max: 0,3, Diff: 0,3, Sum: 4,7
>> [0,680s][trace][gc,phases ] GC(5) Universe Roots (ms): Min:
>> 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
>> [0,680s][trace][gc,phases ] GC(5) JNI Handles Roots (ms):
>> Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
>> [0,680s][trace][gc,phases ] GC(5) ObjectSynchronizer Roots
>> (ms): Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
>> [0,680s][trace][gc,phases ] GC(5) FlatProfiler Roots (ms):
>> Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
>> [0,680s][trace][gc,phases ] GC(5) Management Roots (ms): Min:
>> 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
>> [0,680s][trace][gc,phases ] GC(5) SystemDictionary Roots (ms):
>> Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
>> [0,680s][trace][gc,phases ] GC(5) CLDG Roots (ms): Min: 0,0,
>> Avg: 0,0, Max: 0,1, Diff: 0,1, Sum: 0,1
>> [0,680s][trace][gc,phases ] GC(5) JVMTI Roots (ms): Min: 0,0,
>> Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
>> [0,680s][trace][gc,phases ] GC(5) CM RefProcessor Roots (ms):
>> Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
>> [0,680s][trace][gc,phases ] GC(5) Wait For Strong CLD (ms):
>> Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
>> [0,680s][trace][gc,phases ] GC(5) Weak CLD Roots (ms): Min:
>> 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
>> [0,680s][trace][gc,phases ] GC(5) SATB Filtering (ms): Min:
>> 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
>> [0,680s][debug][gc,phases ] GC(5) Update RS (ms): Min: 0,2,
>> Avg: 0,6, Max: 3,9, Diff: 3,7, Sum: 12,8
>> [0,680s][debug][gc,phases ] GC(5) Processed Buffers: Min: 0,
>> Avg: 1,1, Max: 4, Diff: 4, Sum: 25
>> [0,680s][trace][gc,phases ] GC(5) Scan HCC (ms): Min: 0,0,
>> Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,1
>> [0,680s][debug][gc,phases ] GC(5) Scan RS (ms): Min: 0,0,
>> Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,2
>> [0,680s][debug][gc,phases ] GC(5) Code Root Scanning (ms):
>> Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
>> [0,680s][debug][gc,phases ] GC(5) Object Copy (ms): Min: 0,0,
>> Avg: 3,0, Max: 3,5, Diff: 3,5, Sum: 70,0
>> [0,680s][debug][gc,phases ] GC(5) Termination (ms): Min: 0,0,
>> Avg: 0,1, Max: 0,2, Diff: 0,2, Sum: 3,4
>> [0,680s][debug][gc,phases ] GC(5) Termination Attempts: Min:
>> 1, Avg: 1,0, Max: 1, Diff: 0, Sum: 23
>> [0,680s][debug][gc,phases ] GC(5) GC Worker Other (ms): Min:
>> 0,0, Avg: 0,2, Max: 3,6, Diff: 3,6, Sum: 3,8
>> [0,680s][debug][gc,phases ] GC(5) GC Worker Total (ms): Min:
>> 3,9, Avg: 4,2, Max: 4,2, Diff: 0,4, Sum: 95,5
>> [0,680s][trace][gc,phases ] GC(5) GC Worker End (ms): Min:
>> 672,6, Avg: 672,6, Max: 672,6, Diff: 0,0
>> [0,680s][info ][gc,phases ] GC(5) Code Roots: 0,0ms
>> [0,680s][debug][gc,phases ] GC(5) Code Roots Fixup: 0,0ms
>> [0,680s][debug][gc,phases ] GC(5) Code Roots Purge: 0,0ms
>> [0,680s][info ][gc,phases ] GC(5) Clear Card Table: 0,1ms
>> [0,680s][info ][gc,phases ] GC(5) Expand Heap After Collection:
>> 0,2ms
>> [0,680s][info ][gc,phases ] GC(5) Free Collection Set: 6,4ms
>> [0,680s][debug][gc,phases ] GC(5) Young Free Collection Set: 6,4ms
>> [0,680s][debug][gc,phases ] GC(5) Non-Young Free Collection
>> Set: 0,0ms
>> [0,680s][info ][gc,phases ] GC(5) Other: 0,9ms
>> [0,680s][debug][gc,phases ] GC(5) Choose CSet: 0,0ms
>> [0,680s][debug][gc,phases ] GC(5) Ref Proc: 0,2ms
>> [0,680s][debug][gc,phases ] GC(5) Ref Enq: 0,0ms
>> [0,680s][debug][gc,phases ] GC(5) Redirty Cards: 0,0ms
>> [0,680s][trace][gc,phases ] GC(5) Parallel Redirty: (ms) Min:
>> 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
>> [0,680s][trace][gc,phases ] GC(5) Redirtied Cards:
>> Min: 0, Avg: 7,4, Max: 171, Diff: 171, Sum: 171
>> [0,680s][debug][gc,phases ] GC(5) Humongous Register: 0,0ms
>> [0,680s][trace][gc,phases ] GC(5) Humongous Total: 0
>> [0,680s][trace][gc,phases ] GC(5) Humongous Candidate: 0
>> [0,680s][debug][gc,phases ] GC(5) Humongous Reclaim: 0,0ms
>> [0,680s][trace][gc,phases ] GC(5) Humongous Reclaimed: 0
>> [0,680s][info ][gc,heap ] GC(5) Eden regions: 29->0(29)
>> [0,680s][info ][gc,heap ] GC(5) Survivor regions: 3->3(4)
>> [0,680s][info ][gc,heap ] GC(5) Old regions: 59->59
>> [0,681s][info ][gc,heap ] GC(5) Humongous regions: 0->0
>> [0,681s][info ][gc,metaspace] GC(5) Metaspace: 2975K->2975K(1056768K)
>> [0,681s][info ][gc ] GC(5) Pause Young (G1 Evacuation Pause)
>> 89M->61M(506M) (0,668s, 0,681s) 12,669ms
>> [0,681s][info ][gc,cpu ] GC(5) User=0,09s Sys=0,00s Real=0,01s
>>
>> Thanks,
>> Bengt
>>
>>
>
More information about the hotspot-gc-dev
mailing list