Bug ID: JDK-8299276 runtime/ClassUnload/UnloadInterfaceTest.java fails with "Test failed: should have been unloaded"

JDK-8299276 : runtime/ClassUnload/UnloadInterfaceTest.java fails with "Test failed: should have been unloaded"

Type: Bug
Component: hotspot
Sub-Component: gc
Affected Version: 20

Priority: P2
Status: Closed
Resolution: Duplicate
OS: os_x
CPU: x86_64

Submitted: 2022-12-22
Updated: 2025-02-18
Resolved: 2023-04-28

Versions (Unresolved/Resolved/Fixed)

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
21Resolved

Related Reports

Duplicate :	JDK-8057586 - Explicit GC ignored if GCLocker is active
Duplicate :	JDK-8299776 - Test runtime/cds/appcds/customLoader/UnloadUnregisteredLoaderTest.java failed: should have been unloaded
Duplicate :	JDK-8301264 - runtime/ClassUnload/DictionaryDependsTest.java fails with "Test failed: should be unloaded"
Duplicate :	JDK-8303032 - runtime/ClassUnload/KeepAliveClassLoader.java fails with "Test failed: should be unloaded"
Relates :	JDK-8301264 - runtime/ClassUnload/DictionaryDependsTest.java fails with "Test failed: should be unloaded"
Relates :	JDK-8057586 - Explicit GC ignored if GCLocker is active
Relates :	JDK-8303032 - runtime/ClassUnload/KeepAliveClassLoader.java fails with "Test failed: should be unloaded"

Description

The following test failed in the JDK20 CI:

runtime/ClassUnload/UnloadInterfaceTest.java

Here's a snippet from the log file:

#section:main
----------messages:(7/557)----------
command: main -Xbootclasspath/a:. -Xmn8m -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI -Xlog:class+unload=trace UnloadInterfaceTest
reason: User specified action: run main/othervm -Xbootclasspath/a:. -Xmn8m -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI -Xlog:class+unload=trace UnloadInterfaceTest 
started: Thu Dec 22 12:27:08 GMT 2022
Mode: othervm [/othervm specified]
Additional options from @modules: --add-modules java.base --add-exports java.base/jdk.internal.misc=ALL-UNNAMED
finished: Thu Dec 22 12:27:09 GMT 2022
elapsed time (seconds): 0.837
----------configuration:(4/111)----------
Boot Layer
  add modules: java.base                   
  add exports: java.base/jdk.internal.misc ALL-UNNAMED

----------System.out:(1/38)----------
className found test.ImplementorClass
----------System.err:(13/904)----------
jdk.test.lib.classloader.ClassUnloadCommon$TestFailure: Test failed: should have been unloaded
	at jdk.test.lib.classloader.ClassUnloadCommon.failIf(ClassUnloadCommon.java:51)
	at UnloadInterfaceTest.run(UnloadInterfaceTest.java:90)
	at UnloadInterfaceTest.main(UnloadInterfaceTest.java:69)
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
	at java.base/java.lang.reflect.Method.invoke(Method.java:578)
	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:125)
	at java.base/java.lang.Thread.run(Thread.java:1623)

JavaTest Message: Test threw exception: jdk.test.lib.classloader.ClassUnloadCommon$TestFailure: Test failed: should have been unloaded
JavaTest Message: shutting down test

STATUS:Failed.`main' threw exception: jdk.test.lib.classloader.ClassUnloadCommon$TestFailure: Test failed: should have been unloaded
----------rerun:(43/8811)*----------

Comments

Here's a log file snippet from the jdk-21+15-1201-tier7 sighting: runtime/ClassUnload/UnloadTest.java #section:main ----------messages:(7/539)---------- command: main -Xbootclasspath/a:. -Xmn8m -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI -Xlog:class+unload=debug UnloadTest reason: User specified action: run main/othervm -Xbootclasspath/a:. -Xmn8m -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI -Xlog:class+unload=debug UnloadTest started: Mon Mar 20 21:00:58 GMT 2023 Mode: othervm [/othervm specified] Additional options from @modules: --add-modules java.base --add-exports java.base/jdk.internal.misc=ALL-UNNAMED finished: Mon Mar 20 21:00:59 GMT 2023 elapsed time (seconds): 1.126 ----------configuration:(4/111)---------- Boot Layer add modules: java.base add exports: java.base/jdk.internal.misc ALL-UNNAMED ----------System.out:(18/1830)---------- Refcount of symbol ClassUnloadCommonClassLoader is 3 [0.608s][info][class,unload] unloading class java.lang.invoke.LambdaForm$MH/0x000000080100a800 0x000000080100a800 [0.608s][info][class,unload] unloading class java.lang.invoke.LambdaForm$MH/0x0000000801009c00 0x0000000801009c00 [0.608s][info][class,unload] unloading class java.lang.invoke.LambdaForm$MH/0x0000000801009800 0x0000000801009800 [0.608s][info][class,unload] unloading class java.lang.invoke.LambdaForm$MH/0x0000000801009400 0x0000000801009400 [0.608s][info][class,unload] unloading class java.lang.invoke.LambdaForm$MH/0x0000000801008800 0x0000000801008800 [0.608s][info][class,unload] unloading class java.lang.invoke.LambdaForm$MH/0x0000000801005800 0x0000000801005800 [0.608s][info][class,unload] unloading class java.lang.invoke.LambdaForm$MH/0x0000000801004000 0x0000000801004000 [0.608s][info][class,unload] unloading class java.lang.invoke.LambdaForm$MH/0x0000000801003800 0x0000000801003800 [0.608s][info][class,unload] unloading class java.lang.invoke.LambdaForm$MH/0x0000000801000400 0x0000000801000400 [0.833s][info][class,unload] unloading class test.Empty 0x0000000801005000 Refcount of symbol ClassUnloadCommonClassLoader is 2 Refcount of symbol ClassUnloadCommonClassLoader is 3 [0.907s][info][class,unload] unloading class java.lang.invoke.LambdaForm$MH/0x0000000801000400 0x0000000801000400 [0.907s][info][class,unload] unloading class java.lang.invoke.LambdaForm$MH/0x0000000801004000 0x0000000801004000 [0.907s][info][class,unload] unloading class java.lang.invoke.LambdaForm$MH/0x0000000801005800 0x0000000801005800 [0.907s][info][class,unload] unloading class java.lang.invoke.LambdaForm$MH/0x0000000801009400 0x0000000801009400 [0.907s][info][class,unload] unloading class java.lang.invoke.LambdaForm$MH/0x000000080100a800 0x000000080100a800 ----------System.err:(13/893)---------- jdk.test.lib.classloader.ClassUnloadCommon$TestFailure: Test failed: should have been unloaded at jdk.test.lib.classloader.ClassUnloadCommon.failIf(ClassUnloadCommon.java:51) at UnloadTest.test_unload_obj_array_klass(UnloadTest.java:113) at UnloadTest.main(UnloadTest.java:55) at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103) at java.base/java.lang.reflect.Method.invoke(Method.java:578) at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:125) at java.base/java.lang.Thread.run(Thread.java:1623) JavaTest Message: Test threw exception: jdk.test.lib.classloader.ClassUnloadCommon$TestFailure: Test failed: should have been unloaded JavaTest Message: shutting down test STATUS:Failed.`main' threw exception: jdk.test.lib.classloader.ClassUnloadCommon$TestFailure: Test failed: should have been unloaded ----------rerun:(43/10021)*----------
20-03-2023
Fwiw, the problem is the gclocker initiated gc suppressing the whitebox full gc (and others).
20-03-2023
I added an assert in WhiteBox.fullGC() and when it fails to do any running, another thread is doing GCLocker::jni_unlock() so it does seem to be the cause.
17-03-2023
The cause being GC suppression by gclocker is a hunch, we do not know exactly. This is the reason why there are different priorities. We do use p5 in the gc team, even if only to remind us about the problem, but they'll get fixed eventually, or closed.
17-03-2023
JDK-8057586 is an old one. Leo gave this a P2 and that one is a P5. (We don't use P5 in runtime because we'll close anything that low). I believe that the GC locker does suppress GC but maybe it should. Maybe WhiteBox.fullGC should wait if there's a GCLocker active or maybe the fix is in GC. What do you think?
17-03-2023
JDK-8057586 shows the same issue with System.gc(), so likely it's the same with whitebox gcs
17-03-2023
Maybe the GC locker suppresses the whitebox gc? I remember some earlier problems like this wrt to GC locker, but I may be completely wrong.
17-03-2023
Maybe not. For WhiteBox.fullGC() we want the GC safepoint. I can reproduce this. Adding -XX:-ExplicitGCInvokesConcurrent also reproduces this.
16-03-2023
Looking at the last failure in runtime/ClassUnload/UnloadTestDuringClassLoaderStatsVMOperation.java there are -Xlog:gc* and in the failed case we have: [0.672s][info][gc ] GC(0) Pause Young (Normal) (GCLocker Initiated GC) 4M->2M(514M) 8.725ms then [0.706s][info][gc,verify,start] Verifying [0.751s][info][gc,verify ] Verifying 45.037ms This should have several log lines like this: [0.228s][info][gc ] GC(1) Pause Full (WhiteBox Initiated Full GC) 2M->1M(10M) 3.479ms ClassUnloadCommon.triggerUnloading() should call WhiteBox full GC. This test calls WhiteBox.fullGC directly. Why doesn't G1 do a full GC? It seems like this should include _wb_full_gc inline static bool is_user_requested_gc(GCCause::Cause cause) { return (cause == GCCause::_java_lang_system_gc \|\| cause == GCCause::_dcmd_gc_run); } Reassigning to GC to have a look. I'm still trying to reproduce this.
16-03-2023
Surely all these ClassUnload test failures are related? Either a common test flaw that doesn't guarantee unloading or else an actual bug in the GC logic related to unloading. Creating a JBS issue per test failure is painful and hides the real scope of the problem. So I am going to add a failure of runtime/ClassUnload/UnloadTestDuringClassLoaderStatsVMOperation.java to this issue.
06-03-2023