RFR: JDK-8152952: Allow G1 phase logging to use individual number of threads
Jon Masamitsu
jon.masamitsu at oracle.com
Thu Mar 31 14:47:05 UTC 2016
On 03/31/2016 12:38 AM, Bengt Rutisson wrote:
>
> Hi Jon,
>
> On 2016-03-31 00:02, Jon Masamitsu wrote:
>>
>>
>> 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.
>
> I see what you mean, but I think the "fabs(array.sum() - expected_sum)
> < epsilon" comparison is easier to map back to the actual use of the
> values. We log the values with one decimal point ("%4.1lf"). Before we
> log millisecond values we multiply with MILLIUNITS, which is 1000. So
> with an epsilon of 0.0001 there won't be any difference that can be
> detected in the log.
>
> I am sure the using the more elaborate scheme that you suggest is more
> correct, but it is harder (at least for me) to directly map back to
> the use of the values to see what the effect will be. So, I would
> prefer to keep the simpler "fabs(array.sum() - expected_sum) <
> epsilon" check.
That's fair.
Again, looks good.
Jon
>
> (I changed the epsilon value from 0.001 to 0.0001 in the webrev.04
> version.)
>
> Thanks,
> Bengt
>
>>
>> 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