RFR: 8137022: Concurrent refinement thread adjustment and (de-)activation suboptimal [v3]

[Kim Barrett]

On Tue, 27 Sep 2022 14:45:40 GMT, Thomas Schatzl <tschatzl at openjdk.org> wrote:

>> src/hotspot/share/gc/g1/g1ConcurrentRefine.cpp line 345:
>> 
>>> 343:                         num_cards,
>>> 344:                         _threads_needed.predicted_cards_at_next_gc(),
>>> 345:                         _threads_needed.predicted_time_until_next_gc_ms());
>> 
>> During my testing with fixed IR jbb I saw this kind of frequently: 
>> 
>> [19,856s][trace][gc,refine      ] Activated worker 0, current: 79255
>> [19,856s][debug][gc,refine      ] Updating refinement threads: wanted 0, cards: 79255, predicted: 79255, time: 0,00ms
>> [19,856s][trace][gc,refine      ] Deactivated worker 0, cards: 79255, refined 0, rate 0,00c/ms
>> [19,906s][trace][gc,refine      ] Activated worker 0, current: 79511
>> [19,906s][debug][gc,refine      ] Updating refinement threads: wanted 0, cards: 79511, predicted: 79511, time: 0,00ms
>> [19,906s][trace][gc,refine      ] Deactivated worker 0, cards: 79511, refined 0, rate 0,00c/ms
>> [19,956s][trace][gc,refine      ] Activated worker 0, current: 79511
>> [19,956s][debug][gc,refine      ] Updating refinement threads: wanted 0, cards: 79511, predicted: 79511, time: 0,00ms
>> [19,956s][trace][gc,refine      ] Deactivated worker 0, cards: 79511, refined 0, rate 0,00c/ms
>> [20,007s][trace][gc,refine      ] Activated worker 0, current: 79511
>> [20,007s][debug][gc,refine      ] Updating refinement threads: wanted 0, cards: 79511, predicted: 79511, time: 0,00ms
>> [20,007s][trace][gc,refine      ] Deactivated worker 0, cards: 79511, refined 0, rate 0,00c/ms
>> [20,057s][trace][gc,refine      ] Activated worker 0, current: 79767
>> [20,057s][debug][gc,refine      ] Updating refinement threads: wanted 0, cards: 79767, predicted: 79767, time: 0,00ms
>> [20,057s][trace][gc,refine      ] Deactivated worker 0, cards: 79767, refined 0, rate 0,00c/ms
>> [20,107s][trace][gc,refine      ] Activated worker 0, current: 79767
>> [20,107s][debug][gc,refine      ] Updating refinement threads: wanted 0, cards: 79767, predicted: 79767, time: 0,00ms
>> [20,107s][trace][gc,refine      ] Deactivated worker 0, cards: 79767, refined 0, rate 0,00c/ms
>> 
>> 
>> From what I can tell, in those cases we are not really updating the refinement threads, but keeping them at 0. I think this log should only be printed under the condition that `new_wanted` is different from `old_wanted`. Makes sense?
>
> I think this is fine as is, we want updates to the current state and predictions too (also currently looking at logs). Maybe there is need for more detailed (trace-level?) logging though, still unsure.

The current cards, predicted cards, and predicted time until GC are, I think, all interesting here.  The point is to give some indication of what the controller is doing and why.  (The activation/deactivation messages are probably less interesting now, but that's why I demoted them to trace level.)  For looking at what's going on with refinement `-Xlog:gc+refine*=debug` is now the thing to use.  I wouldn't want to demote the above to trace level, and only logging on changes to wanted wouldn't provide that additional detail that I found useful in making sure things were working properly.

-------------

PR: https://git.openjdk.org/jdk/pull/10256