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