RFR: JDK-8150068: Log the main G1 phases at info level
kirk at kodewerk.com
kirk at kodewerk.com
Thu Feb 18 08:40:26 UTC 2016
Hi Bengt,
In my opinion, the information currently provided by PrintGCDetails is the bare minimum level of detail that I would like to see. The information generated by -Xlog:gc*,gc+phases=debug below is about that level of detail. In particular, the object copy times and RSet refinement times are of particular interest most of the time. It would be nice to not have to use a “debug” setting to get this level of detail.
Kind regards,
Kirk
> On Feb 17, 2016, at 5:00 PM, Bengt Rutisson <bengt.rutisson at oracle.com> 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
>
>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 496 bytes
Desc: Message signed with OpenPGP using GPGMail
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20160218/d1d77b70/signature.asc>
More information about the hotspot-gc-dev
mailing list