RFR: JDK-8152952: Allow G1 phase logging to use individual number of threads
Bengt Rutisson
bengt.rutisson at oracle.com
Thu Mar 31 07:29:21 UTC 2016
Hi Jon,
Thanks a lot for looking at this!
Comments inline.
Updated webrev:
http://cr.openjdk.java.net/~brutisso/8152952/webrev.04/
Diff compared to last version:
http://cr.openjdk.java.net/~brutisso/8152952/webrev.03-04.diff/
On 2016-03-30 22:50, Jon Masamitsu wrote:
>
>
> 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
Fixed.
>
> 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.
Yes, good catch. I noticed this also and fixed the tests yesterday as
you noted in your other email.
>
> 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 - - - - - - - - - -
> - - - - - - - - - - -
I think the " -" adds value when you consider that different threads do
different work. The out put might look like:
[2,996s][trace][gc,phases ] GC(26) Thread Roots (ms):
Min: 0.1, Avg: 0.15, Max: 0.2, Diff: 0.1, Sum: 0.3, Workers: 2
[2,996s][trace][gc,phases,task ] GC(26)
- 0.2 - - - - 0.1 - - - - - - - - - - - - - - - -
[2,996s][trace][gc,phases ] GC(26) StringTable Roots (ms):
Min: 0.1, Avg: 0.2, Max: 0.3, Diff: 0.2, Sum: 0.3, Workers: 3
[2,996s][trace][gc,phases,task ] GC(26)
- - - - - - - 0.3 - - - 0.2 0.1 - - - - - - - - - -
It is not very readable but you look closely it will at least be
possible to see which threads did what work.
>
> 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.
It was intended that it should always be printed. In what cases is it
not printed? From your example it looks like it is missing from the "GC
Worker Start" logging, but in my runs that line also get the "Workers" info:
[0,582s][trace][gc,phases] GC(0) GC Worker Start (ms): Min: 574,2,
Avg: 574,3, Max: 574,3, Diff: 0,0, Workers: 2
[0,582s][trace][gc,phases,task] GC(0)
574,2 574,3 - - - - - - - - - - - - - - - - - - - - -
[0,582s][debug][gc,phases ] GC(0) Ext Root Scanning (ms):
Min: 1,8, Avg: 1,8, Max: 1,8, Diff: 0,0, Sum: 3,5, Workers: 2
[0,582s][trace][gc,phases,task] GC(0)
1,8 1,8 - - - - - - - - - - - - - - - - - - - - -
[0,582s][trace][gc,phases ] GC(0) Thread Roots (ms):
Min: 0,0, Avg: 0,8, Max: 1,6, Diff: 1,6, Sum: 1,6, Workers: 2
[0,582s][trace][gc,phases,task] GC(0)
0,0 1,6 - - - - - - - - - - - - - - - - - - - - -
> 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 }
Changed to contributing_threads.
>
>
> Rest looks good.
Great. Thanks!
Bengt
>
> 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