Bug ID: JDK-8355092 Increased concurrent refinement activity may decrease throughput after JDK-8137022

Type: Bug
Component: hotspot
Sub-Component: gc
Affected Version: 21,25

Priority: P4
Status: Open
Resolution: Unresolved
OS: windows

Submitted: 2025-04-21
Updated: 2025-05-20

JDK 26
26Unresolved

After JDK-8137022, some applications may experience longer processing times. This phenomenon occurs on 2-core Windows Server 2022 configuration, and not on a 4-core Windows Server 2022 or 2-core RHEL 9.4 configuration. Also, if '-XX: -G1UseConcRefinement' is specified, this problem does not occur.

The application installs and starts around 300 OSGi bundles, then launches the Felix framework.
```
org.osgi.framework.launch.Framework framework;
...
framework.getBundleContext().installBundle("xxx").start();
framework.start();
```

As a result of my investigation, There's an increase in CPU time for G1 Refine threads compared to before the fix.
environment: Windows Server 2022, 2 core x 2394 Mhz, 8GB memory

- jdk17 (before the fix)
processing time: 4286 ms
CPU time for G1 Refine#0: 10.41 ms

- jdk21 (after the fix)
processing time: 6111 ms
CPU time for G1 Refine#0: 1635.42 ms

I don't find the same phenomenon in the following environments:
Windows Server 2022, 4 core x 2600 Mhz, 8GB memory
RHEL9.4, 2 core x 2.40 hHz, 8GB memory

Will the JDK-8137022 fixes affect throughput performance?

Moving to 26, as most likely this will be fixed with JDK-8340827 that is unlikely to land in 25.
20-05-2025
[~kbarrett] I attached the GC logs to this issue. > Where were these numbers obtained from: I obtained the total time that threads from the total time between each "Activated worker" and "Deactivated worker." ``` [0.317s][debug][gc,refine] Activated worker 0, on threshold: 768, current: 1086 [0.318s][debug][gc,refine] Deactivated worker 0, off threshold: 512, current: 454, refined cards: 632 ``` The time obtained from this log is 0.001s. > Also, adding "gc+refine+stats=debug" logging may also be interesting. > Also, maybe "gc+ergo+refine=debug" logging. These logs showed little difference in the number of GC cycles and time per GC cycle between jdk21 and jdk17. Does adjust_after_gc() affect it? It is called at the end of a GC to prepare for refinement during the next concurrent phase. Also, if G1UseConcRefinement is disabled, that processing is skipped.
16-05-2025
[~tkiriyama] Where were these numbers obtained from: " As a result, the total time that threads active has also increased. jdk17: 0.043s jdk21: 2.186s " It would be helpful to have the full log, if you could add it as an attachment to this issue. Also, adding "gc+refine+stats=debug" logging may also be interesting. Also, maybe "gc+ergo+refine=debug" logging. This is expected: " Fewer G1 Concurrent Refinement threads run on jdk21. jdk17: 2 jdk21: 1 " This is also expected, as with jdk21 the primary refinement thread wakes up periodically to (more accurately) poll for work, rather than in jdk17 being triggered by the store barrier when there is (less accurately) work to be done. " On the other hand, the thread is activated more often on jdk21. jdk17: 19 times jdk21: 50 times "
14-05-2025
[~tschatzl] Thank you. I run with `gc+refine=trace` logging. - jdk17 (before the fix) ``` [0.317s][debug][gc,refine] Activated worker 0, on threshold: 768, current: 1086 [0.318s][debug][gc,refine] Deactivated worker 0, off threshold: 512, current: 454, refined cards: 632 [1.236s][debug][gc,refine] Activated worker 0, on threshold: 768, current: 1409 [1.237s][debug][gc,refine] Deactivated worker 0, off threshold: 512, current: 512, refined cards: 897 ... [4.359s][debug][gc,refine] Activated worker 0, on threshold: 1004, current: 3285 [4.364s][debug][gc,refine] Deactivated worker 0, off threshold: 748, current: 582, refined cards: 2703 [4.364s][debug][gc,refine] Activated worker 1, on threshold: 2244, current: 582 [4.364s][debug][gc,refine] Deactivated worker 1, off threshold: 1496, current: 582, refined cards: 0 [4.608s][debug][gc,refine] Stopping 0 [4.609s][debug][gc,refine] Stopping 1 ``` - jdk21(after the fix) ``` [0.413s][trace][gc,refine] Activated worker 0, current: 182 [0.419s][debug][gc,refine] Concurrent refinement: wanted 0, cards: 182, predicted: 182, time: 0.00ms [0.420s][trace][gc,refine] Deactivated worker 0, cards: 182, refined 0, rate 0.00c/ms [0.481s][trace][gc,refine] Activated worker 0, current: 182 [0.482s][debug][gc,refine] Concurrent refinement: wanted 0, cards: 182, predicted: 182, time: 0.00ms [0.482s][trace][gc,refine] Deactivated worker 0, cards: 182, refined 0, rate 0.00c/ms ... [6.882s][trace][gc,refine] Activated worker 0, current: 3824 [6.882s][debug][gc,refine] Concurrent refinement: wanted 0, cards: 3824, predicted: 4204, time: 302.59ms [6.882s][trace][gc,refine] Deactivated worker 0, cards: 3824, refined 0, rate 0.00c/ms [6.960s][trace][gc,refine] Activated worker 0, current: 3824 [6.960s][debug][gc,refine] Concurrent refinement: wanted 0, cards: 3824, predicted: 4038, time: 170.23ms [6.960s][trace][gc,refine] Deactivated worker 0, cards: 3824, refined 0, rate 0.00c/ms [6.964s][debug][gc,refine] Stopping 0 ``` There are some differences. Fewer G1 Concurrent Refinement threads run on jdk21. jdk17: 2 jdk21: 1 On the other hand, the thread is activated more often on jdk21. jdk17: 19 times jdk21: 50 times The average time between a thread being activated and being deactivated has also increased. jdk17: 0.002s jdk21: 0.04s As a result, the total time that threads active has also increased. jdk17: 0.043s jdk21: 2.186s
14-05-2025
Surprising to see regressions most likely due to that change. Can you run with `gc+refine=debug` logging to try to understand what is happening?
23-04-2025