United StatesChange Country, Oracle Worldwide Web Sites Communities I am a... I want to...
Bug ID: JDK-6946048 G1: improvements to +PrintGCDetails output
JDK-6946048 : G1: improvements to +PrintGCDetails output

Details
Type:
Enhancement
Submit Date:
2010-04-21
Status:
Closed
Updated Date:
2011-03-08
Project Name:
JDK
Resolved Date:
2011-03-08
Component:
hotspot
OS:
generic
Sub-Component:
gc
CPU:
generic
Priority:
P4
Resolution:
Fixed
Affected Versions:
hs18
Fixed Versions:
hs19 (b04)

Related Reports
Backport:
Backport:
Backport:
Backport:

Sub Tasks

Description
This CR is proposing a couple of improvements to G1's +PrintGCDetails output. Consider the output for a particular pause, for example:

1.449: [GC pause (young), 0.01570246 secs]
   [Parallel Time:  14.1 ms]
      [Update RS (Start) (ms):  1449.1  1449.0  1449.0  1449.0  1449.0  1449.0  1449.0  1449.1  1449.1  1449.1  1449.2  1449.2  1449.2  1449.4  1449.4  1449.4]
      [Update RS (ms):  0.0  0.3  0.1  0.1  0.3  0.2  0.2  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
       Avg:   0.1, Min:   0.0, Max:   0.3]
         [Processed Buffers : 0 2 1 1 1 3 2 0 0 0 0 0 0 0 0 0
          Sum: 10, Avg: 0, Min: 0, Max: 3]
      [Ext Root Scanning (ms):  0.1  0.2  0.1  0.1  0.1  0.1  0.0  0.0  0.1  0.1  0.1  0.1  0.0  0.1  0.1  0.0
       Avg:   0.1, Min:   0.0, Max:   0.2]
      [Mark Stack Scanning (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Scan-Only Scanning (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
         [Scan-Only Regions : 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
          Sum: 0, Avg: 0, Min: 0, Max: 0]
      [Scan RS (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Object Copy (ms):  5.8  4.9  8.2  7.8  5.8  6.9  5.2  10.3  7.4  9.1  9.6  6.6  6.1  4.7  10.2  8.4
       Avg:   7.3, Min:   4.7, Max:  10.3]
      [Termination (ms):  7.4  7.9  2.4  5.2  4.7  6.0  7.8  0.3  3.1  1.4  0.9  3.8  6.7  7.9  0.0  1.8
       Avg:   4.2, Min:   0.0, Max:   7.9]
      [Other:   2.5 ms]
   [Clear CT:   1.4 ms]
   [Other:   0.1 ms]
   [ 96M->96M(512M)]

First, it would be helpful to know the time stamps of when each GC thread started working and finished working. We have an approximation of the former ("Update RS (Start) (ms)"), but not the latter. We should remove the "Update RS (Start) (ms)" lines and introduce "Start Timestamps (ms)" and "End Timestamp (ms)" instead.

Second, the output does report the amount of time each GC thread spent in termination. However, it doesn't report how many times it enters / exits termination. So, we should add that (let's call it "Termination Cycles").

                                    

Comments
EVALUATION

See Description.
                                     
2010-04-21
SUGGESTED FIX

The updated output looks like this:

4.280: [GC pause (young), 0.04342999 secs]
   [Parallel Time:  42.9 ms]
      [GC Worker Start Time (ms):  4279.8  4279.9  4279.9  4280.4]
      [Update RS (ms):  1.1  0.9  0.9  0.0
       Avg:   0.7, Min:   0.0, Max:   1.1]
         [Processed Buffers : 8 7 4 0
          Sum: 19, Avg: 4, Min: 0, Max: 8]
      [Ext Root Scanning (ms):  0.4  0.4  0.4  2.0
       Avg:   0.8, Min:   0.4, Max:   2.0]
      [Mark Stack Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Scan RS (ms):  3.4  3.4  3.5  2.6
       Avg:   3.2, Min:   2.6, Max:   3.5]
      [Object Copy (ms):  37.7  37.7  37.7  37.6
       Avg:  37.7, Min:  37.6, Max:  37.7]
      [Termination (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
         [Termination Cycles : 1 2 2 2
          Sum: 7, Avg: 1, Min: 1, Max: 2]
      [GC Worker End Time (ms):  4322.7  4322.7  4322.6  4322.7]
      [Other:   0.4 ms]
   [Clear CT:   0.1 ms]
   [Other:   0.4 ms]
   [ 52M->34M(64M)]
                                     
2010-04-22
EVALUATION

http://hg.openjdk.java.net/jdk7/hotspot-gc/hotspot/rev/215576b54709
                                     
2010-06-23



Hardware and Software, Engineered to Work Together