RFR: JDK-8150068: Log the main G1 phases at info level
Bengt Rutisson
bengt.rutisson at oracle.com
Wed Feb 17 16:00:24 UTC 2016
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