RFR: JDK-8150068: Log the main G1 phases at info level
Bengt Rutisson
bengt.rutisson at oracle.com
Mon Feb 22 12:19:47 UTC 2016
Hi again,
Now that JDK-8149013 has been pushed the only remaining caller of
G1GCPhaseTimes::accounted_time_ms() was G1GCPhaseTimes::print(). It
makes the code easier to follow if the calculation of the accounted time
is inlined in the print method. Here's an updated webrev where
accounted_time_ms() has been removed and inlined in the print() method
instead.
http://cr.openjdk.java.net/~brutisso/8150068/webrev.01/
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