jdk_foreign_0_FAILED - java/foreign/TestHandshake.java

[JasonFengJ9]

Failure link

https://openj9-jenkins.osuosl.org/job/Test_openjdk16_j9_sanity.openjdk_ppc64_aix_Nightly/55/consoleFull

22:09:40  openjdk version "16.0.1-internal" 2021-04-20
22:09:40  OpenJDK Runtime Environment (build 16.0.1-internal+0-adhoc.****.BuildJDK16ppc64aixNightly)
22:09:40  Eclipse OpenJ9 VM (build master-074746f7710, JRE 16 AIX ppc64-64-Bit Compressed References 20210718_55 (JIT enabled, AOT enabled)
22:09:40  OpenJ9   - 074746f7710
22:09:40  OMR      - 88427d6420f
22:09:40  JCL      - 5dd08a5cc3f based on jdk-16.0.1+9)

Rerun in Grinder

Optional info

Failure output (captured from console output)

06:14:39  ===============================================
06:14:39  java/foreign/TestHandshake.java
06:14:39  Total tests run: 6, Failures: 1, Skips: 0
06:14:39  ===============================================
06:14:39  

06:14:39  ...
06:14:39  Output overflow:
06:14:39  JT Harness has limited the test output to the text
06:14:39  at the beginning and the end, so that you can see how the
06:14:39  test began, and how it completed.
06:14:39  
06:14:39  If you need to see more of the output from the test,
06:14:39  set the system property javatest.maxOutputSize to a higher
06:14:39  value. The current value is 100000
06:14:39  ...

06:14:39  STDERR:
06:14:39  WARNING: Using incubator modules: jdk.incubator.foreign
06:14:39  java.lang.Exception: failures: 1
06:14:39  	at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:96)
06:14:39  	at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:54)
06:14:39  	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
06:14:39  	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:78)
06:14:39  	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
06:14:39  	at java.base/java.lang.reflect.Method.invoke(Method.java:567)
06:14:39  	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
06:14:39  	at java.base/java.lang.Thread.run(Thread.java:883)
06:14:39  
06:14:39  JavaTest Message: Test threw exception: java.lang.Exception: failures: 1

06:14:39  rerun:
06:14:39  cd /home/jenkins/workspace/Test_openjdk16_j9_sanity.openjdk_ppc64_aix_Nightly/aqa-tests/TKG/output_16266607888323/jdk_foreign_0/work/scratch && \
06:14:39  DISPLAY=:0 \
06:14:39  HOME=/home/jenkins \
06:14:39  LANG=en_US \
06:14:39  PATH=/bin:/usr/bin:/usr/sbin \
06:14:39  TZ=EST5EDT \
06:14:39  CLASSPATH=/home/jenkins/workspace/Test_openjdk16_j9_sanity.openjdk_ppc64_aix_Nightly/aqa-tests/TKG/output_16266607888323/jdk_foreign_0/work/classes/java/foreign/TestHandshake.d:/home/jenkins/workspace/Test_openjdk16_j9_sanity.openjdk_ppc64_aix_Nightly/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/foreign:/home/jenkins/workspace/Test_openjdk16_j9_sanity.openjdk_ppc64_aix_Nightly/jvmtest/openjdk/jtreg/lib/testng.jar:/home/jenkins/workspace/Test_openjdk16_j9_sanity.openjdk_ppc64_aix_Nightly/jvmtest/openjdk/jtreg/lib/jcommander.jar:/home/jenkins/workspace/Test_openjdk16_j9_sanity.openjdk_ppc64_aix_Nightly/jvmtest/openjdk/jtreg/lib/javatest.jar:/home/jenkins/workspace/Test_openjdk16_j9_sanity.openjdk_ppc64_aix_Nightly/jvmtest/openjdk/jtreg/lib/jtreg.jar \
06:14:39      /home/jenkins/workspace/Test_openjdk16_j9_sanity.openjdk_ppc64_aix_Nightly/openjdkbinary/j2sdk-image/bin/java \
06:14:39          -Dtest.vm.opts='-ea -esa -Xmx512m --add-modules jdk.incubator.foreign -XX:+UseCompressedOops' \
06:14:39          -Dtest.tool.vm.opts='-J-ea -J-esa -J-Xmx512m -J--add-modules -Jjdk.incubator.foreign -J-XX:+UseCompressedOops' \
06:14:39          -Dtest.compiler.opts= \
06:14:39          -Dtest.java.opts= \
06:14:39          -Dtest.jdk=/home/jenkins/workspace/Test_openjdk16_j9_sanity.openjdk_ppc64_aix_Nightly/openjdkbinary/j2sdk-image \
06:14:39          -Dcompile.jdk=/home/jenkins/workspace/Test_openjdk16_j9_sanity.openjdk_ppc64_aix_Nightly/openjdkbinary/j2sdk-image \
06:14:39          -Dtest.timeout.factor=8.0 \
06:14:39          -Dtest.nativepath=/home/jenkins/workspace/Test_openjdk16_j9_sanity.openjdk_ppc64_aix_Nightly/openjdkbinary/openjdk-test-image/jdk/jtreg/native \
06:14:39          -Dtest.root=/home/jenkins/workspace/Test_openjdk16_j9_sanity.openjdk_ppc64_aix_Nightly/aqa-tests/openjdk/openjdk-jdk/test/jdk \
06:14:39          -Dtest.name=java/foreign/TestHandshake.java \
06:14:39          -Dtest.file=/home/jenkins/workspace/Test_openjdk16_j9_sanity.openjdk_ppc64_aix_Nightly/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/foreign/TestHandshake.java \
06:14:39          -Dtest.src=/home/jenkins/workspace/Test_openjdk16_j9_sanity.openjdk_ppc64_aix_Nightly/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/foreign \
06:14:39          -Dtest.src.path=/home/jenkins/workspace/Test_openjdk16_j9_sanity.openjdk_ppc64_aix_Nightly/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/foreign \
06:14:39          -Dtest.classes=/home/jenkins/workspace/Test_openjdk16_j9_sanity.openjdk_ppc64_aix_Nightly/aqa-tests/TKG/output_16266607888323/jdk_foreign_0/work/classes/java/foreign/TestHandshake.d \
06:14:39          -Dtest.class.path=/home/jenkins/workspace/Test_openjdk16_j9_sanity.openjdk_ppc64_aix_Nightly/aqa-tests/TKG/output_16266607888323/jdk_foreign_0/work/classes/java/foreign/TestHandshake.d \
06:14:39          -Dtest.class.path.prefix=/home/jenkins/workspace/Test_openjdk16_j9_sanity.openjdk_ppc64_aix_Nightly/aqa-tests/TKG/output_16266607888323/jdk_foreign_0/work/classes/java/foreign/TestHandshake.d:/home/jenkins/workspace/Test_openjdk16_j9_sanity.openjdk_ppc64_aix_Nightly/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/foreign \
06:14:39          -Dtest.modules='jdk.incubator.foreign java.base/jdk.internal.vm.annotation java.base/jdk.internal.misc' \
06:14:39          --add-modules jdk.incubator.foreign,java.base \
06:14:39          --add-exports java.base/jdk.internal.vm.annotation=ALL-UNNAMED \
06:14:39          --add-exports java.base/jdk.internal.misc=ALL-UNNAMED \
06:14:39          -ea \
06:14:39          -esa \
06:14:39          -Xmx512m \
06:14:39          -XX:+UseCompressedOops \
06:14:39          -Djava.library.path=/home/jenkins/workspace/Test_openjdk16_j9_sanity.openjdk_ppc64_aix_Nightly/openjdkbinary/openjdk-test-image/jdk/jtreg/native \
06:14:39          -Xint \
06:14:39          com.sun.javatest.regtest.agent.MainWrapper /home/jenkins/workspace/Test_openjdk16_j9_sanity.openjdk_ppc64_aix_Nightly/aqa-tests/TKG/output_16266607888323/jdk_foreign_0/work/java/foreign/TestHandshake.d/testng.1.jta java/foreign/TestHandshake.java false TestHandshake
06:14:39  
06:14:39  TEST RESULT: Failed. Execution failed: `main' threw exception: java.lang.Exception: failures: 1
06:14:39  --------------------------------------------------
06:15:34  Test results: passed: 30; failed: 1
06:15:43  Report written to /home/jenkins/workspace/Test_openjdk16_j9_sanity.openjdk_ppc64_aix_Nightly/jvmtest/openjdk/report/html/report.html
06:15:43  Results written to /home/jenkins/workspace/Test_openjdk16_j9_sanity.openjdk_ppc64_aix_Nightly/aqa-tests/TKG/output_16266607888323/jdk_foreign_0/work
06:15:43  Error: Some tests failed or other problems occurred.
06:15:43  
06:15:43  jdk_foreign_0_FAILED

[JasonFengJ9]

A slightly different error at JDK16 0.27 release build https://openj9-jenkins.osuosl.org/job/Test_openjdk16_j9_sanity.openjdk_x86-64_windows_Release/6/consoleFull

08:31:49  openjdk version "16.0.2-internal" 2021-07-21
08:31:49  OpenJDK Runtime Environment (build 16.0.2-internal+0-adhoc.****.buildjdk16x86-64windowsrelease)
08:31:49  Eclipse OpenJ9 VM (build openj9-0.27.0, JRE 16 Windows Server 2012 R2 amd64-64-Bit Compressed References 20210722_7 (JIT enabled, AOT enabled)
08:31:49  OpenJ9   - 1851b0074f8
08:31:49  OMR      - 9db1c87
08:31:49  JCL      - 50b0cc91164 based on jdk-16.0.2+3)

Rerun in Grinder

09:26:56  --------------------------------------------------
09:26:56  TEST: java/foreign/TestHandshake.java

09:26:56  STDERR:
09:26:56  WARNING: Using incubator modules: jdk.incubator.foreign
09:26:56  java.lang.NullPointerException
09:26:56  	at java.base/jdk.internal.util.ArraysSupport.vectorizedMismatch(ArraysSupport.java)
09:26:56  	at java.base/jdk.internal.misc.ScopedMemoryAccess.vectorizedMismatchInternal(ScopedMemoryAccess.java:236)
09:26:56  	at java.base/jdk.internal.misc.ScopedMemoryAccess.vectorizedMismatch(ScopedMemoryAccess.java:217)
09:26:56  	at jdk.incubator.foreign/jdk.internal.foreign.AbstractMemorySegmentImpl.vectorizedMismatchLargeForBytes(AbstractMemorySegmentImpl.java:203)
09:26:56  	at jdk.incubator.foreign/jdk.internal.foreign.AbstractMemorySegmentImpl.mismatch(AbstractMemorySegmentImpl.java:166)
09:26:56  	at TestHandshake$SegmentMismatchAccessor.doAccess(TestHandshake.java:189)
09:26:56  	at TestHandshake$AbstractSegmentAccessor.run(TestHandshake.java:94)
09:26:56  	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
09:26:56  	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630)
09:26:56  	at java.base/java.lang.Thread.run(Thread.java:883)
09:26:56  STATUS:Failed.`main' threw exception: java.lang.NullPointerException

[JasonFengJ9]

Another one at JDK 16 0.27 release build https://openj9-jenkins.osuosl.org/job/Test_openjdk16_j9_sanity.openjdk_ppc64le_linux_Release/6/consoleFull

11:03:11  test TestHandshake.testHandshake("SegmentMismatchAccessor", TestHandshake$$Lambda$30/0x000000006ece8dc0@f523f37a): failure
11:03:11  java.lang.AssertionError: expected [true] but found [false]
11:03:11  	at org.testng.Assert.fail(Assert.java:94)
11:03:11  	at org.testng.Assert.failNotEquals(Assert.java:496)
11:03:11  	at org.testng.Assert.assertTrue(Assert.java:42)
11:03:11  	at org.testng.Assert.assertTrue(Assert.java:52)
11:03:11  	at TestHandshake.testHandshake(TestHandshake.java:76)
11:03:11  	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
11:03:11  	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:78)
11:03:11  	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
11:03:11  	at java.base/java.lang.reflect.Method.invoke(Method.java:567)
11:03:11  	at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:85)
11:03:11  	at org.testng.internal.Invoker.invokeMethod(Invoker.java:639)
11:03:11  	at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:821)
11:03:11  	at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:1131)
11:03:11  	at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:125)
11:03:11  	at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:108)
11:03:11  	at org.testng.TestRunner.privateRun(TestRunner.java:773)
11:03:11  	at org.testng.TestRunner.run(TestRunner.java:623)
11:03:11  	at org.testng.SuiteRunner.runTest(SuiteRunner.java:357)
11:03:11  	at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:352)
11:03:11  	at org.testng.SuiteRunner.privateRun(SuiteRunner.java:310)
11:03:11  	at org.testng.SuiteRunner.run(SuiteRunner.java:259)
11:03:11  	at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:52)
11:03:11  	at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:86)
11:03:11  	at org.testng.TestNG.runSuitesSequentially(TestNG.java:1185)
11:03:11  	at org.testng.TestNG.runSuitesLocally(TestNG.java:1110)
11:03:11  	at org.testng.TestNG.run(TestNG.java:1018)
11:03:11  	at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:94)
11:03:11  	at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:54)
11:03:11  	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
11:03:11  	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:78)
11:03:11  	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
11:03:11  	at java.base/java.lang.reflect.Method.invoke(Method.java:567)
11:03:11  	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
11:03:11  	at java.base/java.lang.Thread.run(Thread.java:883)

11:03:11  ===============================================
11:03:11  java/foreign/TestHandshake.java
11:03:11  Total tests run: 6, Failures: 1, Skips: 0
11:03:11  ===============================================
11:03:11  
11:03:11  STDERR:
11:03:11  WARNING: Using incubator modules: jdk.incubator.foreign
11:03:11  java.lang.Exception: failures: 1
11:03:11  	at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:96)
11:03:11  	at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:54)
11:03:11  	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
11:03:11  	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:78)
11:03:11  	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
11:03:11  	at java.base/java.lang.reflect.Method.invoke(Method.java:567)
11:03:11  	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
11:03:11  	at java.base/java.lang.Thread.run(Thread.java:883)
11:03:11  
11:03:11  JavaTest Message: Test threw exception: java.lang.Exception: failures: 1

11:04:20  jdk_foreign_0_FAILED

[tajila]

@EricYangIBM This may be related to #13234

[EricYangIBM]

I believe the issue is that https://github.com/ibmruntimes/openj9-openjdk-jdk16/blob/openj9/test/jdk/java/foreign/TestHandshake.java#L242 keeps throwing and looping without ever successfully closing the segment because there is always another thread accessing that segment. I'm not sure why it only happens for the SegmentMismatchAccessor variation, I think it is because ScopedMemoryAccess.vectorizedMismatch takes longer and therefore gives fewer opportunities to close the segment.

Would having closeScope0 interrupt threads that are accessing the scope during close with an exception increase the success rate of close? I get the feeling that this is an issue with the test since it is a try until success - there is a probability that close will always happen during segment access.

Also, I am intermittently getting this failure locally. Do the release builds run the test over multiple iterations?

[pshipton]

Release builds don't do anything special, they just run the test.

[tajila]

Can you set MAX_EXECUTOR_WAIT_SECONDS to a longer timeout to see if that fixes the issue.

[EricYangIBM]

Can you set MAX_EXECUTOR_WAIT_SECONDS to a longer timeout to see if that fixes the issue.

Testing that right now, but I think it will. https://hyc-runtimes-jenkins.swg-devops.com/view/Test_grinder/job/Grinder/17169/console shows SegmentMismatchAccessor iterations that successfully close the segment (e.g. at 348 ms, 5049 ms for iteration 0 and 1 for the last grinder iteration). If the timeout is increased I think there will be more successful SegmentMismatchAccessor iterations.

[EricYangIBM]

I think the problem is that SegmentMismatchAccessor takes too long (it compares two 1 000 000 byte native memory segments) which prevents the main thread from obtaining the lock. In https://hyc-runtimes-jenkins.swg-devops.com/view/Test_grinder/job/Grinder/17198/consoleFull you can see that an accessor (thread) often holds the lock for 2000 ms. In the hotspot implementation closeScope interrupts accessor threads so the closer thread can immediately acquire the lock. Our implementation doesn't do this so we get the long hold times.

[EricYangIBM]

Update: Replacing https://github.com/ibmruntimes/openj9-openjdk-jdk16/blob/openj9/test/jdk/java/foreign/TestHandshake.java#L76 with

while (!accessExecutor.isTerminated()) {
    Thread.sleep(5000);
}

eventually results in the test passing (locally on x86-64 linux). I will open a PR to exclude this test and an issue to add interrupts to closeScope0.