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").
|