jdk_io_1_FAILED java/io/Serializable/subclassGC/SubclassGC.java java.lang.Error

[JasonFengJ9]

Failure link

From an internal build(rhel7le-rtp-rt3-1):

java version "21.0.3-beta" 2024-04-16
IBM Semeru Runtime Certified Edition 21.0.3+7-202403280004 (build 21.0.3-beta+7-202403280004)
Eclipse OpenJ9 VM 21.0.3+7-202403280004 (build master-87d656319, JRE 21 Linux ppc64le-64-Bit Compressed References 20240328_133 (JIT enabled, AOT enabled)
OpenJ9   - 87d656319
OMR      - 6391cf4bb
JCL      - 29b3f94dd based on jdk-21.0.3+7)

Rerun in Grinder - Change TARGET to run only the failed test targets.

Optional info

Failure output (captured from console output)

[2024-03-28T01:02:40.892Z] variation: Mode650
[2024-03-28T01:02:40.892Z] JVM_OPTIONS:  -XX:-UseCompressedOops -Xverbosegclog 

[2024-03-28T01:06:37.993Z] TEST: java/io/Serializable/subclassGC/SubclassGC.java

[2024-03-28T01:06:37.994Z] STDERR:
[2024-03-28T01:06:37.994Z] Start Garbage Collection right now
[2024-03-28T01:06:37.994Z] java.lang.Error
[2024-03-28T01:06:37.994Z] 	at SubclassGC.main(SubclassGC.java:82)
[2024-03-28T01:06:37.994Z] 	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
[2024-03-28T01:06:37.994Z] 	at java.base/java.lang.reflect.Method.invoke(Method.java:586)
[2024-03-28T01:06:37.994Z] 	at com.sun.javatest.regtest.agent.MainWrapper$MainTask.run(MainWrapper.java:138)
[2024-03-28T01:06:37.994Z] 	at java.base/java.lang.Thread.run(Thread.java:1595)
[2024-03-28T01:06:37.994Z] 
[2024-03-28T01:06:37.994Z] JavaTest Message: Test threw exception: java.lang.Error

[2024-03-28T01:07:25.148Z] jdk_io_1_FAILED

50x internal grinder - #19246 (comment)

Also seen JDK22 ppc64le_linux(rhel8le-rtp-rt8-1), JDK22 s390x_linux(sles15s390x-svl-rt8-1)

[pshipton]

Grinder passed on rhel7le-svl-rt6-1, rhel7le-rtp-rt7-1, ubu20le-svl-rt4-1, ubu20le-svl-rt5-1.
Failed 1/10 on rhel8le-svl-rt7-1.

The test is waiting for 1000ms after a System.gc() for a weak reference to be added to the ReferenceQueue, but it timed out.

@dmitripivkine fyi

[dmitripivkine]

I guess it might be another manifestation of #9651, object pointer is stored in the hard root. Currently there is no results stored for this exception, so nothing to look at.
@pshipton would you please help with command line to get a system core?

[dmitripivkine]

There were no weak references enqueued for last GC. However there has been number of references enqueued before:

  <references type="weak" candidates="66" cleared="10" enqueued="10" />
  <references type="weak" candidates="105" cleared="15" enqueued="15" />
  <references type="weak" candidates="162" cleared="24" enqueued="24" />
  <references type="weak" candidates="114" cleared="18" enqueued="18" />
  <references type="weak" candidates="113" cleared="27" enqueued="27" />
  <references type="weak" candidates="136" cleared="42" enqueued="42" />
  <references type="weak" candidates="250" cleared="2" enqueued="2" />
  <references type="weak" candidates="248" cleared="0" enqueued="0" />

[pshipton]

Probably the easiest approach is to modify the test to call com.ibm.jvm.Dump.SystemDump() when it fails.

[JasonFengJ9]

Also seen at JDK22 aarch64_linux(cent7-aarch64-1)

[2024-04-02T04:00:45.002Z] variation: Mode650
[2024-04-02T04:00:45.002Z] JVM_OPTIONS:  -XX:-UseCompressedOops -Xverbosegclog 

[2024-04-02T04:03:49.830Z] TEST: java/io/Serializable/subclassGC/SubclassGC.java

[2024-04-02T04:03:49.831Z] Start Garbage Collection right now
[2024-04-02T04:03:49.831Z] java.lang.Error
[2024-04-02T04:03:49.831Z] 	at SubclassGC.main(SubclassGC.java:82)
[2024-04-02T04:03:49.831Z] 	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
[2024-04-02T04:03:49.831Z] 	at java.base/java.lang.reflect.Method.invoke(Method.java:586)
[2024-04-02T04:03:49.831Z] 	at com.sun.javatest.regtest.agent.MainWrapper$MainTask.run(MainWrapper.java:138)
[2024-04-02T04:03:49.831Z] 	at java.base/java.lang.Thread.run(Thread.java:1582)
[2024-04-02T04:03:49.831Z] 
[2024-04-02T04:03:49.831Z] JavaTest Message: Test threw exception: java.lang.Error

[2024-04-02T04:04:12.969Z] jdk_io_1_FAILED

[pshipton]

Internal build
jdk22 0.45 RC1

[pshipton]

See if the failure can be duplicated running only the individual test (it can).
https://hyc-runtimes-jenkins.swg-devops.com/view/Test_grinder/job/Grinder/40182/

[pshipton]

@dmitripivkine there is a system dump to look at.

https://hyc-runtimes-jenkins.swg-devops.com/job/Grinder_iteration_8/691
https://na.artifactory.swg-devops.com/artifactory/sys-rt-generic-local/hyc-runtimes-jenkins.swg-devops.com/Grinder_iteration_8/691/openjdk_test_output.tar.gz

[dmitripivkine]

I noticed that java/lang/invoke/MemberName objects (we added Finalization processing to recently) have pointer back to class object. It means class can't be unloaded until all of such objects are processed in Finalization. This test calls System.gc() once. It might be not enough to reach the point when class can be unloaded. So, at least we should try to call System.gc() twice (or even more times) and see if this problem goes away.

[pshipton]

Trying a grinder with two calls to System.gc()
https://hyc-runtimes-jenkins.swg-devops.com/job/Grinder/40263/ - this and a previous grinder passed

[keithc-ca]

Is the plan that the changes above will be reverted when we have the solution anticipated in ibmruntimes/openj9-openjdk-jdk#759 (comment)?

[pshipton]

Yes, we can do that, if we remember to do so.

[pshipton]

I can keep this open and assigned to the latest milestone as a reminder.

[dmitripivkine]

There is nothing to do with this item until new implementation for handling java/lang/invoke/MemberName objects is in place. Moving to the next milestone.