RFR(S): 7096030: G1: PrintGCDetails enhancements

[John Cuthbertson]

Hi Everyone,

I have a new webrev for this change based upon some initial feedback, 
which can be found here: http://cr.openjdk.java.net/~johnc/7096030/webrev.1/

Changes in this webrev include:
* Coalescing the GC Worker Other time and Parallel Other Time into a 
single "GC Worker Other" time.
* Modifying some of the tags in the PrintGCDetails output
* The order of the phases in the PrintGCDetails when 
ParallelGCThreads==0 now matches that of the parallel case.

New output:

151.550: [GC pause (young), 0.57693560 secs]
   [SATB Drain Time:   0.0 ms]
   [Parallel Time: 553.7 ms]
      [GC Worker Start (ms):  151550.7  151550.7  151550.7  151551.3
       Avg: 151550.9, Min: 151550.7, Max: 151551.3, Diff:   0.6]
      [Ext Root Scanning (ms):  2.8  2.8  3.0  2.6
       Avg:   2.8, Min:   2.6, Max:   3.0, Diff:   0.4]
      [Mark Stack Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0, Diff:   0.0]
      [Update RS (ms):  5.1  5.6  3.9  5.3
       Avg:   5.0, Min:   3.9, Max:   5.6, Diff:   1.7]
         [Processed Buffers : 3 3 6 5
          Sum: 17, Avg: 4, Min: 3, Max: 6, Diff: 3]
      [Scan RS (ms):  14.0  13.7  14.8  13.3
       Avg:  13.9, Min:  13.3, Max:  14.8, Diff:   1.5]
      [Object Copy (ms):  531.4  531.2  531.5  531.5
       Avg: 531.4, Min: 531.2, Max: 531.5, Diff:   0.3]
      [Termination (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0, Diff:   0.0]
         [Termination Attempts : 1 1 1 1
          Sum: 4, Avg: 1, Min: 1, Max: 1, Diff: 0]
      [GC Worker End (ms):  152104.1  152104.1  152104.0  152104.0
       Avg: 152104.1, Min: 152104.0, Max: 152104.1, Diff:   0.1]
      [GC Worker (ms):  553.4  553.4  553.3  552.7
       Avg: 553.2, Min: 552.7, Max: 553.4, Diff:   0.7]
      [GC Worker Other (ms):  0.4  0.4  0.5  1.0
       Avg:   0.6, Min:   0.4, Max:   1.0, Diff:   0.6]
   [Clear CT:   1.4 ms]
   [Other:  21.8 ms]
      [Choose CSet:   0.0 ms]
      [Ref Proc:   2.8 ms]
      [Ref Enq:   0.0 ms]
   [Eden: 1230M(1230M)->0B(1230M) Survivors: 134M->134M Heap: 
3312M(4096M)->2216M(4096M)]
 [Times: user=0.77 sys=0.61, real=0.58 secs]

Thanks,

JohnC

On 10/12/11 09:55, John Cuthbertson wrote:
> Hi Everyone,
>
> Can I have a a couple of volunteers review these changes? The webrev 
> can be found at: http://cr.openjdk.java.net/~johnc/7096030/webrev.0/
>
> Description:
> While looking at the PrintGCDetails output from running some large 
> applications, it was noticed that there seemed to be a large amount of 
> time listed as "Parallel Other Time" which couldn't be accounted for. 
> To account for this I have replaced the single overall "Parallel Other 
> Time" with two times that is reported for each GC worker thread:
>
> GC Worker Other Times
> This is the unaccounted time for each GC worker between its start and 
> end times. It is calculated as "GC Worker Time" minus the sum of the 
> times for that worker given for "Ext. Root Scanning", "Mark Stack 
> Scanning", "RS Update", "RS Scanning", "Object Copying", and 
> "Termination".
>
> Parallel Other Times
> This is the difference between the overall elapsed time for the 
> parallel phase and the elapsed time for each GC worker. This includes 
> the overhead of starting and stopping the worker, as well as executing 
> the destructors of any objects created in the G1ParTask::work() method.
>
> Both these times (for each GC worker) should be close to 0.0.
>
> I was thinking of coalescing these into a single time but decided to 
> leave them separate as they tell us slightly different things.
>
> I also changed the order in the PrintGCDetails output to reflect the 
> order of the different phases within the parallel code. An example of 
> the new format is:
>
> 112.115: [GC pause (young) (initial-mark), 0.73699803 secs]
>    [Parallel Time: 729.9 ms]
>       [GC Worker Start Time (ms):  112115.5  112115.5  112115.6  112115.6
>        Avg: 112115.5, Min: 112115.5, Max: 112115.6, Diff:   0.1]
>       [Ext Root Scanning (ms):  2.7  2.7  3.2  3.1
>        Avg:   2.9, Min:   2.7, Max:   3.2, Diff:   0.5]
>       [Mark Stack Scanning (ms):  0.0  0.0  0.0  0.0
>        Avg:   0.0, Min:   0.0, Max:   0.0, Diff:   0.0]
>       [Update RS (ms):  7.3  7.5  5.1  5.0
>        Avg:   6.2, Min:   5.0, Max:   7.5, Diff:   2.5]
>          [Processed Buffers : 4 6 3 4
>           Sum: 17, Avg: 4, Min: 3, Max: 6, Diff: 3]
>       [Scan RS (ms):  14.0  13.6  15.0  15.8
>        Avg:  14.6, Min:  13.6, Max:  15.8, Diff:   2.2]
>       [Object Copy (ms):  705.6  705.6  706.1  705.5
>        Avg: 705.7, Min: 705.5, Max: 706.1, Diff:   0.6]
>       [Termination (ms):  0.0  0.0  0.0  0.0
>        Avg:   0.0, Min:   0.0, Max:   0.0, Diff:   0.0]
>          [Termination Attempts : 1 1 1 1
>           Sum: 4, Avg: 1, Min: 1, Max: 1, Diff: 0]
>       [GC Worker End Time (ms):  112845.0  112845.1  112845.1  112845.1
>        Avg: 112845.1, Min: 112845.0, Max: 112845.1, Diff:   0.1]
>       [GC Worker Times (ms):  729.5  729.5  729.5  729.5
>        Avg: 729.5, Min: 729.5, Max: 729.5, Diff:   0.1]
>       [GC Worker Other Times (ms):  0.0  0.1  0.1  0.1
>        Avg:   0.1, Min:   0.0, Max:   0.1, Diff:   0.1]
>       [Parallel Other Times (ms):  0.4  0.4  0.4  0.4
>        Avg:   0.4, Min:   0.4, Max:   0.4, Diff:   0.1]
>    [Clear CT:   1.1 ms]
>    [Other:   6.0 ms]
>       [Choose CSet:   0.0 ms]
>       [Ref Proc:   0.2 ms]
>       [Ref Enq:   0.0 ms]
>    [Eden: 1230M(1230M)->0B(1230M) Survivors: 134M->134M Heap: 
> 3753M(4096M)->2657M(4096M)]
>
> Additionally, during RSet scanning, I now stack allocate the 
> DirtyCardToOopClosure objects that were being allocated in the GC 
> worker's ResourceArea. Executing the destructor of a ResourceMark and 
> freeing the spaced allocated in the worker threads' ResourceArea 
> objects  was the main contributor to the large "Parallel Other Time".
>
> Testing: OpenDS on linux and Solaris with 4G, 16G, and 26G heaps; the 
> GC test suite, and jprt.
>
> Thanks,
>
> JohnC