JDK-8364503 : gc/g1/TestCodeCacheUnloadDuringConcCycle.java fails because of race printing to stdout
  • Type: Bug
  • Component: hotspot
  • Sub-Component: gc
  • Affected Version: 26
  • Priority: P4
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2025-08-01
  • Updated: 2025-08-26
  • Resolved: 2025-08-07
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 25 JDK 26
25.0.2Fixed 26 b10Fixed
Related Reports
Causes :  
JDK-8350621 - Code cache stops scheduling GC
Description
Output and diagnostic info for process 1847633 was saved into 'pid-1847633-output.log'
[0.019s][info][gc] Using G1
[0.020s][debug][gc] ConcGCThreads: 3 offset 29
[0.020s][debug][gc] ParallelGCThreads: 13
[0.020s][trace][gc] MarkStackSize: 4096k  MarkStackSizeMax: 524288k
[0.020s][debug][gc] Initialize mark stack with 4096 chunks, maximum 536870912
CompileCommand: compileonly gc/g1/SomeClass.* bool compileonly = true
[0.074s][info ][codecache] Triggering threshold (12.749%) GC due to allocating 15.004% since last unloading (0.000% used -> 15.004% used)
[0.074s][trace][gc       ] main: Try Collect Concurrently (CodeCache GC Threshold): attempt 1
[0.099s][debug][gc       ] GC(0) Allocated 1 survivor 0 old percent total 5.26% (10%)
[0.100s][info ][gc       ] GC(0) Pause Young (Concurrent Start) (CodeCache GC Threshold) 1M->1M(20M) 4.442ms
[0.100s][info ][gc       ] GC(1) Concurrent Mark Cycle
[0.100s][trace][gc       ] main: Try Collect Concurrently (CodeCache GC Threshold): complete true
[0.112s][info ][codecache] Unknown code cache pressure; don't age code
[0.113s][info ][gc       ] GC(1) Pause Remark 1M->1M(20M) 0.711ms
[0.117s][info ][gc       ] GC(1) Pause Cleanup 1M->1M(20M) 0.053ms
[0.120s][info ][gc       ] GC(1) Concurrent Mark Cycle 20.111ms
[0.155s][trace][gc       ] main: Try Collect Concurrently (WhiteBox Initiated Run to Breakpoint): attempt 1
[0.159s][debug][gc       ] GC(2) Allocated 1 survivor 0 old percent total 5.26% (10%)
[0.159s][info ][gc       ] GC(2) Pause Young (Concurrent Start) (WhiteBox Initiated Run to Breakpoint) 2M->1M(20M) 3.193ms
[0.159s][info ][gc       ] GC(3) Concurrent Mark Cycle
[0.159s][trace][gc       ] main: Try Collect Concurrently (WhiteBox Initiated Run to Breakpoint): complete true
[0.171s][info ][codecache] Allocation rate: 847.861 KB/s, time to aggressive unloading: 3.286 s, cold timeout: 0.822 s, cold gc count: 14, used: 1.279 MB (15.990%), last used: 1.231 MB (15.382%), gc interval: 0.059 s
[0.171s][info ][gc       ] GC(3) Pause Remark 1M->1M(20M) 0.617ms
Try to trigger code cache GC
Compiled 0 classes
Compiled 20 classes
Compiled 40 classes
Compiled 60 classes
Compiled 80 classes
Compiled 100 classes
Compiled 120 classes
Compiled 140 classes
Compiled 160 classes
[2.053s][info ][codecache] Triggering threshold (10.952%) GC due to allocating 10.995% since last unloading (15.990% used -> 26.985% used)
[2.053s][trace][gc       ] C1 CompilerThread0: Try Collect Concurrently (CodeCache GC Threshold): attempt 1
[2.053s][trace][gc       ] C1 CompilerThread0: Try Collect Concurrently (CodeCache GC Threshold): wait
Compiled 180 classes
Compilation done, compiled 200 classes
[2.507s][info ][gc       ] GC(3) Pause Cleanup 9M->9M(20M) 0.060ms
[2.508s][info ][gc       ] GC(3) Concurrent Mark Cycle 2348.621ms
[2.508s][trace][gc       ] C1 CompilerThread0: Try Collect Concurrently (CodeCache GC Threshold): retry after in-progress
[2.508s][trace][gc       ] C1 CompilerThread0: Try Collect Concurrently (CodeCache GC Threshold): attempt 2
[2.508s][trace][gc       ] C1 CompilerThread0: Try Collect Concurrently (CodeCache GC Threshold): whitebox control stall
[2.509s][trace][gc       ] C1 CompilerThread0: Try Collect Concurrently (CodeCache GC Threshold): attempt 3
[2.518s][debug][gc       ] GC(4) Allocated 2 survivor 0 old percent total 11.11% (10%)
[2.518s][info ][gc       ] GC(4) Pause Young (Concurrent Start) (CodeCache GC Threshold) 9M->2M(20M) 9.454ms
[2.518s][info ][gc       ] GC(5) Concurrent Mark Cycle
[2.518s][trace][gc       ] C1 CompilerThread0: Try Collect Concurrently (CodeCache GC Threshold): complete true
Marker for this test
[2.538s][info ][codecache] Allocation rate: 984.519 KB/s, time to aggressive unloading: 0.134 s, cold timeout: 0.034 s, cold gc count: 2, used: 3.871 MB (48.386%), last used: 1.279 MB (15.990%), gc interval: 1.213 s
[2.538s][info ][gc       ] GC(5) Pause Remark 2M->2M(20M) 4.377ms
[2.543s][info ][gc       ] GC(5) Pause Cleanup 2M->2M(20M) 0.056ms
[2.543s][info ][gc       ] GC(5) Concurrent Mark Cycle 25.200ms
Compiled 0 classes
Compiled 20 classes
Compiled 40 classes
Compiled 60 classes
Compiled 80 classes
Compiled 100 classes
Compiled 120 classes
Compiled 140 classes
Compiled 160 classes
Compiled 180 classes
Compilation done, compiled 200 classes

----------System.err:(15/1223)----------
java.lang.RuntimeException: Could not find a CodeCache GC Threshold GC after finishing the concurrent cycle: expected true, was false
	at jdk.test.lib.Asserts.fail(Asserts.java:715)
	at jdk.test.lib.Asserts.assertTrue(Asserts.java:545)
	at gc.g1.TestCodeCacheUnloadDuringConcCycle.runAndCheckTest(TestCodeCacheUnloadDuringConcCycle.java:94)
	at gc.g1.TestCodeCacheUnloadDuringConcCycle.allTests(TestCodeCacheUnloadDuringConcCycle.java:99)
	at gc.g1.TestCodeCacheUnloadDuringConcCycle.main(TestCodeCacheUnloadDuringConcCycle.java:104)
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
	at java.base/java.lang.reflect.Method.invoke(Method.java:565)
	at com.sun.javatest.regtest.agent.MainWrapper$MainTask.run(MainWrapper.java:138)
	at java.base/java.lang.Thread.run(Thread.java:1474)
Comments
A pull request was submitted for review. Branch: master URL: https://git.openjdk.org/jdk25u/pull/83 Date: 2025-08-11 14:15:26 +0000
25-08-2025
jdk25u-fix-request: Impact: fixes the bug in the test for JDK-8350621 also requested for jdk25u backport. Risk: has been running fine for almost three weeks in mainline now, so risk should be low at this point Testing: tier1-5 with no different failures than without this change
11-08-2025
Looks like a new test from JDK-8350621, linking that one up. David, this I think is the answer why it showed up recently.
08-08-2025
Changeset: c56fb0b6 Branch: master Author: Thomas Schatzl <tschatzl@openjdk.org> Date: 2025-08-07 08:40:42 +0000 URL: https://git.openjdk.org/jdk/commit/c56fb0b6eff7d3f36bc65f300b784e0dd73c563e
07-08-2025
What changed to cause this to suddenly start appearing?
01-08-2025
A pull request was submitted for review. Branch: master URL: https://git.openjdk.org/jdk/pull/26592 Date: 2025-08-01 10:31:53 +0000
01-08-2025
This looks like a test bug due to race in gc log output and console output: the test tries to force a codecache caused concurrent mark cycle in specific situations during the concurrent cycle using breakpoints. Then it proceeds with the test, i.e. lets the whitebox breakpoint concurrent cycle proceed until finish and then waits for a re-start of that concurrent mark cycle. This occurs (the last "Pause Young (Concurrent Start) (CodeCache GC Threshold" message), but to get this particular message *after* the concurrent cycle, the tests ignores everything before the "Marker for this test" message. In this case it looks like this marker came after the message we were waiting for - log and console output are not synchronized.
01-08-2025