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

Jon Masamitsu jon.masamitsu at oracle.com
Thu Mar 31 14:45:14 UTC 2016



On 03/31/2016 12:29 AM, Bengt Rutisson wrote:
>
> 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.

Ok.  That's reasonable.

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

Ok.  I'll let you know if I see it again.  Might have been user error.

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

All looks good.

Thanks.

Jon

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