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