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

Jon Masamitsu jon.masamitsu at oracle.com
Wed Mar 30 20:50:55 UTC 2016



On 03/30/2016 07:27 AM, 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/

Copyright

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

157 const char* expected_string = "Test array Min: 5, Avg: 6,0, Max: 7, 
Diff: 2, Sum: 12, Workers: 2\n";

The "6,0," should be "6.0" in the US.

Maybe you've already discussed this but the " - " in the details output 
doesn't seem to add much
for me.

56 void WorkerDataArray<double>::WDAPrinter::details(const 
WorkerDataArray<double>* phase, outputStream* out) {
   57   out->print("%-25s", "");
58 for (uint i = 0; i < phase->_length; ++i) {
59 double value = phase->get(i);
60 if (value != phase->uninitialized()) {
   61       out->print(" %4.1lf", phase->get(i) * 1000.0);
62 } else {
63 out->print(" -");
64 }
   65   }

[1.345s][trace][gc,phases            ] GC(0)      GC Worker Start 
(ms):     Min: 1049.0, Avg: 1004.8, Max: 1056.2, Diff:  7.3
[1.345s][trace][gc,phases,task       ] 
GC(0)                                1049.0 1049.0 1049.0 1049.0 1049.0 
1049.0 1049.0 1049.0 1049.0 1049.0 1049.0 1049.0 1049.0 1049.0 1049.0 
1049.1 1049.1 1052.2 1052.2 1052.2 1056.2 1056.2 1056.2

[0.505s][trace][gc,phases            ] GC(1)       GC Worker Start 
(ms):     Min: 501.4, Avg: 501.5, Max: 501.5, Diff:  0.0, Workers: 2
[0.505s][trace][gc,phases,task       ] 
GC(1)                                 501.4 501.5 - - - - - - - - - - - 
- - - - - - - - - -

Worker count (e.g. "Workers: 2" above) is only printed sometimes? Maybe 
Thomas already
commented on that?  I'd like it better if it was always printed.

http://cr.openjdk.java.net/~brutisso/8152952/webrev.02/src/share/vm/gc/g1/workerDataArray.inline.hpp.frames.html

Use of the variable name "active_threads" is going to confuse at
least me since that is used other places to mean the number of
threads trying to do work (not just the threads that actually
found work to do so had data).  "contributing_threads" is
a suggestion.

122 uint active_threads = 0;
123 for (uint i = start; i < _length; ++i) {
  124       T value = get(i);
125 if (value != uninitialized()) {
  126         max = MAX2(max, value);
  127         min = MIN2(min, value);
  128         sum += value;
129 active_threads++;
130 }
  131     }


Rest looks good.

Thanks.

Jon

>>
>> 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