RFR(S): 7096030: G1: PrintGCDetails enhancements

John Cuthbertson john.cuthbertson at oracle.com
Mon Oct 17 15:20:07 PDT 2011


Hi Everyone,

A new webrev for this CR can be found at: 
http://cr.openjdk.java.net/~johnc/7096030/webrev.2/ based upon some 
additional feedback.

Changes in this webrev include:
* Some minor reorganization in G1CollectorPolicy::record_collection_end().
* Removal of the _satb_drain_time_set flag.
* In addition to the SATB Drain Time and the # of processed SATB 
buffers, output of Mark Stack Scanning is now dependent on whether 
marking is active.
* Modified the TraceGen0Time output to be ordered consistently with 
PrintGCDetails.

Testing: specjvm98 and OpenDS; manually checked that the TraceGen0Time 
and TraceGen1Time output values are consistent with summarizing the 
pause data.

Thanks,

JohnC

On 10/14/11 10:17, John Cuthbertson wrote:
> 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
>



More information about the hotspot-gc-dev mailing list