LayersTest didn't find VM_CLASS_UNLOAD adoptopenjdk/test/modularity/hello/Hello

[pshipton]

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.system_s390x_linux_Nightly_testList_0/193
LayersTest_0

T1  JUnit version 4.12
T1  stderr 00:44:13.872*0x69800            j9mm.291      - cleanUpClassLoadersStart about to trigger VM_CLASS_UNLOAD hook for class 000000000034BF00(adoptopenjdk/test/modularity/helper/pkgOne/HelperClass)
T1  .
T1  Time: 2.442
T1  
T1  OK (1 test)
T1  
STF 20:44:14.043 - Monitoring Report Summary:
STF 20:44:14.043 -   o Process T1  ended with the expected exit code (0)
STF 20:44:14.043 - 
STF 20:44:14.043 - +------ Step 2 - Check output
STF 20:44:14.043 - | Count file matches
STF 20:44:14.043 - |   TargetFile:         /home/jenkins/workspace/Test_openjdk21_j9_sanity.system_s390x_linux_Nightly_testList_0/aqa-tests/TKG/output_17115785735682/LayersTest_0/20240327-204405-LayersTest/results/1.T1.stderr
STF 20:44:14.043 - |   ExpectedNumMatches: 1
STF 20:44:14.043 - |   SearchStrings:      ["VM_CLASS_UNLOAD.*adoptopenjdk/test/modularity/hello/Hello"]
STF 20:44:14.043 - |
**FAILED** at step 2 (Check output). Expected return value=1 Actual=0 at /home/jenkins/workspace/Test_openjdk21_j9_sanity.system_s390x_linux_Nightly_testList_0/aqa-tests/TKG/../TKG/output_17115785735682/LayersTest_0/20240327-204405-LayersTest/execute.pl line 122.

[pshipton]

10x x 5 grinder https://openj9-jenkins.osuosl.org/job/Grinder/3421/

Failed 1/10 on rh7-390-2
and 1/10 on rh7-390-3
Passed on ub20-390-3a, rh7-390-1, ub20-390-5

[pshipton]

@dmitripivkine pls take a look. I haven't seen this fail before. I got a core file via https://openj9-jenkins.osuosl.org/job/Grinder/3423/
https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Test/Grinder/3423/system_test_output.tar.gz

Trying with -Xint as well.
20x x 5 grinder https://openj9-jenkins.osuosl.org/job/Grinder/3425/ - passed

[pshipton]

@hzongaro the grinder results indicate it may be the JIT preventing the class from being unloaded.

One interesting thing is that the class which is still unloaded (HelperClass) is the second one loaded. It's the first class loaded (Hello) which doesn't get unloaded.

https://github.com/adoptium/aqa-systemtest/blob/master/openjdk.test.modularity/src/tests/com.test/net/adoptopenjdk/test/modularity/junit/TestLayers.java#L63-L69

[JasonFengJ9]

Also seen in an internal JDK21 s390x_linux(rhel84s390x-fips2)

[2024-03-28T01:54:14.499Z] variation: Mode150
[2024-03-28T01:54:14.499Z] JVM_OPTIONS:  -XX:+UseCompressedOops

[2024-03-28T01:54:23.734Z] STF 01:54:23.315 - +------ Step 2 - Check output
[2024-03-28T01:54:23.734Z] STF 01:54:23.315 - | Count file matches
[2024-03-28T01:54:23.734Z] STF 01:54:23.315 - |   TargetFile:         /home/jenkins/workspace/Test_openjdk21_j9_sanity.system_s390x_linux_testList_1/aqa-tests/TKG/output_17115886472384/LayersTest_0/20240328-015414-LayersTest/results/1.T1.stderr
[2024-03-28T01:54:23.734Z] STF 01:54:23.315 - |   ExpectedNumMatches: 1
[2024-03-28T01:54:23.734Z] STF 01:54:23.315 - |   SearchStrings:      ["VM_CLASS_UNLOAD.*adoptopenjdk/test/modularity/hello/Hello"]
[2024-03-28T01:54:23.734Z] STF 01:54:23.315 - |
[2024-03-28T01:54:23.734Z] **FAILED** at step 2 (Check output). Expected return value=1 Actual=0 at /home/jenkins/workspace/Test_openjdk21_j9_sanity.system_s390x_linux_testList_1/aqa-tests/TKG/../TKG/output_17115886472384/LayersTest_0/20240328-015414-LayersTest/execute.pl line 122.
[2024-03-28T01:54:23.734Z] STF 01:54:23.335 - **FAILED** execute script failed. Expected return value=0 Actual=1

[2024-03-28T01:54:23.734Z] LayersTest_0_FAILED

[pshipton]

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.system_s390x_linux_Release_testList_2/18/ - ub20-390-4
https://openj9-jenkins.osuosl.org/job/Test_openjdk22_j9_sanity.system_s390x_linux_Release_testList_0/6 - ub20-390-2
LayersTest_1

Changes from last release build
218cf60...440a9f2
ibmruntimes/openj9-openjdk-jdk21@d85f56a...5b5adb3

[pshipton]

@hzongaro this seems a regression in the 0.44 release.

[hzongaro]

Trying some grinder runs with earlier builds. . . .

[dmitripivkine]

from the core:
there is alive java/lang/invoke/MemberName !j9object 0x000000000D129B28 pointed to class object !j9object 0x000000000C93FC60 for adoptopenjdk/test/modularity/hello/Helloclass 0x33B600:

> !j9object 0x000000000D129B28
!J9Object 0x000000000D129B28 {
	struct J9Class* clazz = !j9class 0xE3700 // java/lang/invoke/MemberName
	Object flags = 0x00000010;
	I lockword = 0x00000000 (offset = 0) (java/lang/Object) <hidden>
	Ljava/lang/Class; clazz = !fj9object 0xc93fc60 (offset = 20) (java/lang/invoke/MemberName) <------
	Ljava/lang/String; name = !fj9object 0xc87d688 (offset = 24) (java/lang/invoke/MemberName)
	Ljava/lang/Object; type = !fj9object 0xc8c04e0 (offset = 28) (java/lang/invoke/MemberName)
	I flags = 0x06010009 (offset = 40) (java/lang/invoke/MemberName)
	Ljava/lang/invoke/ResolvedMethodName; method = !fj9object 0x0 (offset = 32) (java/lang/invoke/MemberName)
	Ljava/lang/Object; resolution = !fj9object 0x0 (offset = 36) (java/lang/invoke/MemberName)
	J vmindex = 0xFFFFFFFFFFFFFFFF (offset = 12) (java/lang/invoke/MemberName) <hidden>
	J vmtarget = 0x000000000033B7E8 (offset = 4) (java/lang/invoke/MemberName) <hidden>
	I finalizeLink = 0x00000000 (offset = 44) (java/lang/invoke/MemberName) <hidden>
}

[hzongaro]

there is alive java/lang/invoke/MemberName !j9object 0x000000000D129B28 pointed to class object !j9object 0x000000000C93FC60 for adoptopenjdk/test/modularity/hello/Helloclass 0x33B600

Sorry for the dumb question, @dmitripivkine, but what's pointing to the MemberName object 0x000000000D129B28?

[hzongaro]

what's pointing to the MemberName object 0x000000000D129B28?

Sorry - I see now that the core file was generated at vmstop, so the reference to that MemberName might well have been on the stack earlier in the run, and no longer exists.

[dmitripivkine]

there is alive java/lang/invoke/MemberName !j9object 0x000000000D129B28 pointed to class object !j9object 0x000000000C93FC60 for adoptopenjdk/test/modularity/hello/Helloclass 0x33B600

Sorry for the dumb question, @dmitripivkine, but what's pointing to the MemberName object 0x000000000D129B28?

This is not a dumb question, this is what I am trying to figure out now.
Not so much success unfortunately. This object is included to JNI Weak Global Refs list. It is not a hard root, it is Clearable. But presence of this object in the list shows it wasn't dead or did not exist at last GC time. This object is not marked as well, so it was created after last Global GC. Also there are two references to this object from Finalizer thread java stack very close to the top (currently empty). It implies it was used in the last Finalization processing.

[pshipton]

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.system_s390x_linux_Nightly_testList_2/196/

[dmitripivkine]

Ah, I guess it might relate to latest @jdmpapin change #19187.
It introduces special handling for java/lang/invoke/MemberName objects. This change keeps track of such objects in the lists (class based) and trims list using Finalization.
@TobiAjila FYI

[dmitripivkine]

If my theory is correct it just takes longer to have this class to be unloaded... We need enqueue MemberName object, run Finalization and only after this Global GC can unload it. But not every Global GC performs class unloading and it should be forced by test.

[pshipton]

Try a grinder with a modified test that does 32 calls to Thread.sleep(); System.gc().
pshipton/aqa-systemtest@3cacf7b81

20x x 6 https://openj9-jenkins.osuosl.org/view/Test/job/Grinder/3434/ - passed

Try 3 calls.
pshipton/aqa-systemtest@68f23eacd93

20x x 6 https://openj9-jenkins.osuosl.org/view/Test/job/Grinder/3435/ - passed

[pshipton]

@dmitripivkine should I create a PR to change the test as per pshipton/aqa-systemtest@68f23eacd93 or do you have a different suggestion?

[dmitripivkine]

@dmitripivkine should I create a PR to change the test as per pshipton/aqa-systemtest@68f23eacd93 or do you have a different suggestion?

Please create PR. I think this fix is good enough. Thank you!

[pshipton]

Created adoptium/aqa-systemtest#488 to update the test.

[pshipton]

adoptium/aqa-tests#5192 updates the test in the v1.0.1 testenv, which is the version used for 0.44.