RFR: JDK-8150068: Log the main G1 phases at info level
Bengt Rutisson
bengt.rutisson at oracle.com
Fri Feb 26 11:48:51 UTC 2016
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