JDK-8325613 : CTW: Stale method cleanup requires GC after Sweeper removal
  • Type: Bug
  • Component: hotspot
  • Sub-Component: compiler
  • Affected Version: 21,22,23
  • Priority: P4
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2024-02-12
  • Updated: 2024-03-27
  • Resolved: 2024-03-14
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 21 JDK 22 JDK 23
21.0.4-oracleFixed 22.0.2Fixed 23 b15Fixed
Related Reports
Relates :  
Relates :  
Relates :  
Description
I was surprised to see that CTW times have regressed considerably in recent JDKs. For example, Linux x86_64 fastdebug time is extremely bad:

$ time CONF=linux-x86_64-server-fastdebug make test TEST="applications/ctw/modules/java_base.java"
real 26m13s
user 71m22s
sys 185m55s

For comparison, the same run in current 17u-dev does it in:
real 2m24s
user 7m32s
sys 0m18s

A brief profiling shows the code spends lot of time spinning for deoptimization here: https://github.com/openjdk/jdk/blob/1358850aa63a2874031ca33eba278432fd09d6ab/src/hotspot/share/runtime/deoptimization.cpp#L193-L195 -- code added by JDK-8300926 in JDK 21. CTW runner deoptimizes methods often to let newer versions of the method to compile.

JDK-8300926 likely explains why "sys" time is this bad: CTW runner executes multiple threads, most of them spending time in kernel yielding. Adding -XX:ActiveProcessorCount=1 helps to avoid this:

$ time CONF=linux-x86_64-server-fastdebug make test TEST="applications/ctw/modules/java_base.java" TEST_VM_OPTS="-XX:ActiveProcessorCount=1"
real 31m42s
user 32m31s
sys 0m17s

If we cannot figure out if JDK-8300926 could be made better, maybe we should be running CTW with 1 thread by default, and rely on external parallelism to utilize resources better.

Note that "real" time is still bad. It might have some relation to JDK-8290025, which removed the sweeper, and that now relies on GC to unload the methods promptly. We might be running into the same issue we fixed earlier when Sweeper was present (JDK-8238247). Might need to call GC explicitly now?
Comments
A pull request was submitted for review. URL: https://git.openjdk.org/jdk21u-dev/pull/370 Date: 2024-03-18 09:55:26 +0000
18-03-2024

A pull request was submitted for review. URL: https://git.openjdk.org/jdk22u/pull/104 Date: 2024-03-18 09:52:07 +0000
18-03-2024

[jdk21u-fix-request] Approval Request from Aleksey Shipilëv Clean backport to improve CTW testing times. CTW tests pass, and much faster with the patch applied. Have been running in my CI for several days without problems. The benefit for testing time is so large I would like to have it in our dev repositories sooner. Risk is low, test only fix.
18-03-2024

[jdk22u-fix-request] Approval Request from Aleksey Shipilëv Clean backport to improve CTW testing times. CTW tests pass, and much faster with the patch applied. Risk is low, test only fix.
18-03-2024

Changeset: 1281e18f Author: Aleksey Shipilev <shade@openjdk.org> Date: 2024-03-14 10:26:49 +0000 URL: https://git.openjdk.org/jdk/commit/1281e18f1447848d7eb5e3bde508ac002b4c390d
14-03-2024

A pull request was submitted for review. URL: https://git.openjdk.org/jdk/pull/18249 Date: 2024-03-12 19:11:42 +0000
12-03-2024

I think both issues are basically due to Sweeper removal. The deopt is slow due to lots of stale methods. The spinning on deopt mutex from multiple threads is a side effect of this, and tuning down the thread count only mitigates contention on that mutex, not the actual issue with deopts being slow. After JDK-8290025, we need to somehow get GCs to clean up the cruft to make quicker progress.
12-03-2024

ILW = Slow deoptimization and/or sweeping, only reported with CTW testing, no workaround = MLH = P4
12-02-2024