RFR: JDK-8152952: Allow G1 phase logging to use individual number of threads

Jon Masamitsu jon.masamitsu at oracle.com
Wed Mar 30 22:02:53 UTC 2016



On 03/30/2016 10:36 AM, Bengt Rutisson wrote:
>
> Hi again,
>
> Another update to the webrev. I talked to Jon a bit and realized that 
> it would be good to have at least a sanity test on the <double> 
> version of WorkerDataArray. I refactored the tests a bit to be more 
> readable and also fixed two issues with the previous versions. The 
> original tests did not handle different locales and also had a too 
> strict double comparison.
>
> Here's an updated webrev:
> http://cr.openjdk.java.net/~brutisso/8152952/webrev.03/
>
> Only the internal VM tests have been changed. Here's a diff compared 
> to the last version:
> http://cr.openjdk.java.net/~brutisso/8152952/webrev.02-03.diff/

This fixes the comment I had about the decimal separators (about "6,0" 
in my earlier mail).

http://cr.openjdk.java.net/~brutisso/8152952/webrev.02-03.diff/src/share/vm/gc/g1/workerDataArray.cpp.frames.html

125 assert(fabs(array.sum() - expected_sum) < epsilon, "Wrong sum, 
expected: %f but got: %f", expected_sum, array.sum());


A comparison like

(fabs(array.sum() - expected_sum) / fabs(array.sum() + expected_sum))  < epsilon

might be better.

Jon

>
> Thanks,
> Bengt
>
> On 2016-03-30 16:27, Bengt Rutisson wrote:
>>
>> One comment at the bottom of this email....
>>
>> On 2016-03-30 16:11, Bengt Rutisson wrote:
>>>
>>> Hi Thomas,
>>>
>>> Thanks for looking at this!
>>>
>>> On 2016-03-30 11:15, Thomas Schatzl wrote:
>>>> Hi Bengt,
>>>>
>>>> On Tue, 2016-03-29 at 14:03 +0200, Bengt Rutisson wrote:
>>>>> Hi everyone,
>>>>>
>>>>> Could I have a couple of reviews for this change?
>>>>>
>>>>> http://cr.openjdk.java.net/~brutisso/8152952/webrev.00/
>>>>> https://bugs.openjdk.java.net/browse/JDK-8152952
>>>>>
>>>>> Currently if you run with UseDynamicNumberOfGCThreads you can
>>>>> potentially get a different number of worker threads each GC. There
>>>>> are improvements coming where we want to select a different number of
>>>>> worker threads for individual phases. The G1GCPhaseTimes and
>>>>> WorkerDataArray structures need to support this.
>>>>>
>>>>> The proposed patch sets all slots in the WorkerDataArray to an
>>>>> uninitialized value and then only print any values that have actually
>>>>> been set for that phase.
>>>>>
>>>>> The patch also extends the log message about the number for worker
>>>>> threads to also say how many it could potentially have used. And it
>>>>> also fixes a missing space in the level 3 and level 4 indentation.
>>>>>
>>>>> After applying this patch and running with -Xlog:gc*,phases*=trace
>>>>> you get output like:
>>>>> [0,581s][info][gc,task ] GC(0) GC Workers: using 2 out of 23
>>>>> [0,588s][info][gc,phases] GC(0)   Evacuate Collection Set: 5,0ms
>>>>> [0,588s][trace][gc,phases] GC(0)       GC Worker Start (ms):     Min:
>>>>> 580,9, Avg: 580,9, Max: 580,9, Diff:  0,0
>>>> It would be useful to have the information about the number of threads
>>>> used for every top-level WorkerDataArray. That might differ for every
>>>> phase in the future. Now it does not matter, because at the moment
>>>> every thread at least sets the time spent to zero (i.e. is forced to),
>>>> but that will not be the case later.
>>>>
>>>> Not working on something is different to taking "zero" time for it.
>>>>
>>>> My suggestion is to add a ", Workers: X" column to the summary 
>>>> output, like
>>>>
>>>>> [0,588s][debug][gc,phases     ] GC(0)     Ext Root Scanning (ms):
>>>>> Min:  1,7, Avg:  1,7, Max:  1,8, Diff:  0,0, Sum:  3,5
>>>> Min:  1,7, Avg:  1,7, Max:  1,8, Diff:  0,0, Sum:  3,5, Workers: 2
>>>
>>> I added that. The log now looks like this:
>>>
>>> [0,613s][debug][gc,phases     ] GC(0)     Ext Root Scanning (ms):   
>>> Min:  2,4, Avg:  2,5, Max:  2,7, Diff:  0,3, Sum: 5,0, Workers: 2
>>>
>>>>
>>>>> [0,589s][trace][gc,phases,task] GC(0)
>>>>> 1,8  1,7   -   -   -   - -   -   -   -   -   -   -   -   - -   -
>>>>> -
>>>>
>>>>> [0,588s][trace][gc,phases,task] GC(0)
>>>>> 580,9 580,9   -   -   - -   -   -   -   -   -   -   -   - -   -   -
>>>> - g1GCPhaseTimes.cpp:109: typo in ASSERT_PHASE_UNINITILAIZED, 
>>>> should be
>>>> ASSERT_PHASE_UNINITIALIZED.
>>>
>>> Fixed. Thanks for catching that! :)
>>>
>>>>
>>>> - ignore the following if wanted: in g1GCPhaseTimes.cpp:127 the if
>>>> -clause is structured to have only the asserts in the if-part. I would
>>>> prefer if the code that performs some useful work would be first, i.e.
>>>> the condition reversed. As mentioned, ymmv.
>>>
>>> Done.
>>>
>>>>
>>>> - I would kind of prefer if ADD_WORKER_KNOWN time were a method 
>>>> instead
>>>> of a macro. In case of an uninitialized value that method could just
>>>> return 0.0, which would be okay for this addition.
>>>
>>> Done.
>>>
>>>>
>>>> - in WorkerDataArray::WDAPrinter::details, the "unknown value" imo 
>>>> does
>>>> not need to be padded out to five spaces or so. I think the main
>>>> motivation for this has been to show the values of the different 
>>>> phases
>>>> of the evacuation phase in the same column.
>>>>
>>>> The details() method for the size_t values is not aligned at all.
>>>>
>>>> The main reason is waste of space. Not sure here, in doubt keep it.
>>>
>>> Removed the padding for both variants.
>>>
>>>>
>>>> - I would prefer if the #include "memory/resourceArea.hpp" were put
>>>> next to the other includes, of course guarded by the define.
>>>
>>> I prefer to keep it closer to the tests. If you have strong opinions 
>>> I can move it up, but since it is only test related I prefer to have 
>>> it there.
>>>
>>>>
>>>> - in workerDataArray.hpp, at the definitions of sum() and average() it
>>>> might be useful to mention what impact on sum/average uninitialized
>>>> values have.
>>>
>>> Added a comment.
>>>
>>>>
>>>> - I would prefer, if a phase has no data, that this would be detected
>>>> automatically and the phase either not printed, or (preferably)
>>>> indicated that it has not been executed. (I could also live with a
>>>> solution where the programmer can choose what happens when there is no
>>>> data. That would probably also remove the dependencies on a lot of
>>>> other components, since as of right now there is quite a bit of
>>>> checking for particular circumstances in G1GCPhaseTimes::print()).
>>>>
>>>> I do not really like the solution based on this change presented for
>>>> JDK-8152428 that the programmer is responsible for explicitly
>>>> specifying that a phase has not been executed. This will be forgotten,
>>>> and only causes unnecessary failures potentially long after a change
>>>> has been committed.
>>>>
>>>> The code to print has to iterate over all elements to sum/average them
>>>> up anyway, so it already knows that there is no data for a particular
>>>> phase.
>>>>
>>>> The reason why I prefer an indication that a phase has not been
>>>> executed is that instead of a missing line that a missing line easy to
>>>> overlook, while a "not executed" line is much more visible.
>>>
>>> I've changed to do mostly what you suggested. A skipped phase now logs:
>>>
>>> [6,339s][trace][gc,phases      ] GC(79)       Parallel Preserve CM 
>>> Refs (ms):: skipped
>>
>> The double ":" should not be there. The log actually looks like:
>>
>> [6,458s][trace][gc,phases      ] GC(82)       Parallel Preserve CM 
>> Refs (ms): skipped
>>
>> And I should also have mentioned that this makes my other fix for 
>> JDK-8152428 void. I will withdraw that fix if this patch gets approved.
>>
>> Thanks,
>> Bengt
>>
>>>
>>> But you can't control that by a configuration on the 
>>> WorkerDataArray. On the other hand you can control it just like you 
>>> did before, but guarding the call in the print() menthod. Like for 
>>> example StringDeduplication does.
>>>
>>> Updated webrev:
>>> http://cr.openjdk.java.net/~brutisso/8152952/webrev.02/
>>>
>>> Diff compared to last version:
>>> http://cr.openjdk.java.net/~brutisso/8152952/webrev.01-02.diff/
>>>
>>> Thanks,
>>> Bengt
>>>
>>>>
>>>> Thanks,
>>>>    Thomas
>>>>
>>>
>>
>



More information about the hotspot-gc-dev mailing list