JDK-6946048 : G1: improvements to +PrintGCDetails output
  • Type: Enhancement
  • Component: hotspot
  • Sub-Component: gc
  • Affected Version: hs18
  • Priority: P4
  • Status: Closed
  • Resolution: Fixed
  • OS: generic
  • CPU: generic
  • Submitted: 2010-04-21
  • Updated: 2013-09-18
  • Resolved: 2011-03-08
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 6 JDK 7 Other
6u21pFixed 7Fixed hs19Fixed
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 http://hg.openjdk.java.net/jdk7/hotspot-gc/hotspot/rev/215576b54709
23-06-2010
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)]
22-04-2010
EVALUATION See Description.
21-04-2010