RFR(S): 7096030: G1: PrintGCDetails enhancements

[John Cuthbertson]

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