RFR: JDK-8150068: Log the main G1 phases at info level

Bengt Rutisson bengt.rutisson at oracle.com
Fri Feb 26 14:15:39 UTC 2016


Here's an updated webrev that is based on top of Thomas recent changes 
for JDK-8150630, JDK-8076463, JDK-8150629 and JDK-8140777:

http://cr.openjdk.java.net/~brutisso/8150068/webrev.02/

I had to do some manual merging so unfortunately it is not easy to 
provide a diff compared to the last version. All merging was in 
g1GCPhaseTimes.cpp and they were due to the addition of PreserveCMReferents.

Thanks,
Bengt

On 2016-02-26 12:48, Bengt Rutisson wrote:
>
> Hi again,
>
> Stefan J did an offline code review of this change and we've updated 
> the patch based on his comments.
>
> Here's an updated webrev:
> http://cr.openjdk.java.net/~brutisso/8150068/webrev.01/
>
> Here's a diff compared to the last version:
> http://cr.openjdk.java.net/~brutisso/8150068/webrev.00-01.diff/
>
> The main changes is to try to get rid of some code duplication in 
> G1GCPhaseTimes by using more templates, macros and moving some 
> printing code to WorkerDataArray.
>
> Also the test was updated to also check that the log messages are 
> logged at the correct level.
>
> Thanks,
> 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