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

[Thomas Schatzl]

On Tue, 27 Sep 2022 13:51:35 GMT, Stefan Johansson <sjohanss at openjdk.org> wrote:

>> Kim Barrett has updated the pull request incrementally with three additional commits since the last revision:
>> 
>>  - wanted vs needed nomenclature
>>  - remove several spurious "scan"
>>  - delay => wait_time_ms
>
> 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.

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

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