Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

OpenJDK java/util/concurrent/tck/JSR166TestCase.java junit test failed, unknown test #17135

Open
pshipton opened this issue Apr 10, 2023 · 26 comments

Comments

@pshipton
Copy link
Member

https://openj9-jenkins.osuosl.org/job/Test_openjdk20_j9_sanity.openjdk_x86-64_windows_Nightly/31
jdk_util_0
java/util/concurrent/tck/JSR166TestCase.java

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

02:55:51  [ JUnit Containers: found 221, started 221, succeeded 185, failed 0, aborted 0, skipped 0]
02:55:51  [ JUnit Tests: found 4084, started 4063, succeeded 4062, failed 1, aborted 0, skipped 0]
02:55:51  
02:55:51  java.lang.Exception: JUnit test failure
02:55:51  	at com.sun.javatest.regtest.agent.JUnitRunner.runWithJUnitPlatform(JUnitRunner.java:150)
02:55:51  	at com.sun.javatest.regtest.agent.JUnitRunner.main(JUnitRunner.java:96)
02:55:51  	at com.sun.javatest.regtest.agent.JUnitRunner.main(JUnitRunner.java:62)
02:55:51  	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
02:55:51  	at java.base/java.lang.reflect.Method.invoke(Method.java:578)
02:55:51  	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:125)
02:55:51  	at java.base/java.lang.Thread.run(Thread.java:1639)
@pshipton
Copy link
Member Author

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_s390x_linux_OMR_testList_1/57/
jdk_util_0
java/util/concurrent/tck/JSR166TestCase.java

06:34:11  [ JUnit Containers: found 222, started 222, succeeded 186, failed 0, aborted 0, skipped 0]
06:34:11  [ JUnit Tests: found 4087, started 4066, succeeded 4065, failed 1, aborted 0, skipped 0]

@pshipton
Copy link
Member Author

@JasonFengJ9
Copy link
Member

JDK17 ppc64le_linux(sles12le-svl-rt7-1)

[2024-04-02T01:28:26.379Z] variation: -Xdump:system:none -Xdump:heap:none -Xdump:system:events=gpf+abort+traceassert+corruptcache Mode650
[2024-04-02T01:28:26.379Z] JVM_OPTIONS:  -Xdump:system:none -Xdump:heap:none -Xdump:system:events=gpf+abort+traceassert+corruptcache -XX:-UseCompressedOops -Xverbosegclog 

[2024-04-02T01:37:10.156Z] TEST: java/util/concurrent/tck/JSR166TestCase.java#others

[2024-04-02T01:37:10.167Z] ...
[2024-04-02T01:37:10.167Z] Output overflow:
[2024-04-02T01:37:10.167Z] JT Harness has limited the test output to the text
[2024-04-02T01:37:10.167Z] at the beginning and the end, so that you can see how the
[2024-04-02T01:37:10.167Z] test began, and how it completed.
[2024-04-02T01:37:10.167Z] 
[2024-04-02T01:37:10.167Z] If you need to see more of the output from the test,
[2024-04-02T01:37:10.167Z] set the system property javatest.maxOutputSize to a higher
[2024-04-02T01:37:10.167Z] value. The current value is 100000
[2024-04-02T01:37:10.167Z] ...

[2024-04-02T01:37:10.170Z] JavaTest Message: JUnit Platform Failure(s): 1
[2024-04-02T01:37:10.170Z] 
[2024-04-02T01:37:10.170Z] [ JUnit Containers: found 218, started 218, succeeded 182, failed 0, aborted 0, skipped 0]
[2024-04-02T01:37:10.170Z] [ JUnit Tests: found 4061, started 4040, succeeded 4039, failed 1, aborted 0, skipped 0]
[2024-04-02T01:37:10.170Z] 
[2024-04-02T01:37:10.170Z] java.lang.Exception: JUnit test failure
[2024-04-02T01:37:10.170Z] 	at com.sun.javatest.regtest.agent.JUnitRunner.runWithJUnitPlatform(JUnitRunner.java:149)
[2024-04-02T01:37:10.170Z] 	at com.sun.javatest.regtest.agent.JUnitRunner.main(JUnitRunner.java:95)
[2024-04-02T01:37:10.170Z] 	at com.sun.javatest.regtest.agent.JUnitRunner.main(JUnitRunner.java:61)
[2024-04-02T01:37:10.170Z] 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[2024-04-02T01:37:10.170Z] 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
[2024-04-02T01:37:10.170Z] 	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[2024-04-02T01:37:10.170Z] 	at java.base/java.lang.reflect.Method.invoke(Method.java:574)
[2024-04-02T01:37:10.170Z] 	at com.sun.javatest.regtest.agent.MainWrapper$MainTask.run(MainWrapper.java:138)
[2024-04-02T01:37:10.170Z] 	at java.base/java.lang.Thread.run(Thread.java:857)
[2024-04-02T01:37:10.170Z] 
[2024-04-02T01:37:10.170Z] JavaTest Message: Test threw exception: java.lang.Exception: JUnit test failure

[2024-04-02T01:58:40.079Z] jdk_util_1_FAILED

@pshipton
Copy link
Member Author

pshipton commented Apr 8, 2024

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_aarch64_linux_Release_testList_0/21
jdk_util_0
java/util/concurrent/tck/JSR166TestCase.java#forkjoinpool-common-parallelism

08:17:40  [ JUnit Containers: found 222, started 222, succeeded 186, failed 0, aborted 0, skipped 0]
08:17:40  [ JUnit Tests: found 4087, started 4066, succeeded 4065, failed 1, aborted 0, skipped 0]

@pshipton
Copy link
Member Author

pshipton commented Jun 27, 2024

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_s390x_linux_Release_testList_1/26
jdk_util_0
java/util/concurrent/tck/JSR166TestCase.java#default

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_x86-64_linux_OpenJDK21_testList_1/19 - ub16x64j96
jdk_util_0
java/util/concurrent/tck/JSR166TestCase.java#default

@pshipton
Copy link
Member Author

pshipton commented Aug 12, 2024

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.openjdk_x86-64_linux_OpenJDK11_testList_0/18/ - ub20-x86-1
jdk_util_0
java/util/concurrent/tck/JSR166TestCase.java#others

@cjjdespres
Copy link
Contributor

@pshipton
Copy link
Member Author

pshipton commented Oct 3, 2024

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_aarch64_linux_Nightly_testList_0/318 - cent9-aarch64-5
jdk_util_1
java/util/concurrent/tck/JSR166TestCase.java#security-manager

@pshipton
Copy link
Member Author

pshipton commented Oct 7, 2024

https://openj9-jenkins.osuosl.org/job/Test_openjdk17_j9_sanity.openjdk_aarch64_linux_Nightly_testList_1/307
jdk_util_0
java/util/concurrent/tck/JSR166TestCase.java#security-manager

@pshipton
Copy link
Member Author

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.openjdk_ppc64le_linux_Nightly_testList_0/83
jdk_util_0
java/util/concurrent/tck/JSR166TestCase.java#forkjoinpool-common-parallelism

@pshipton
Copy link
Member Author

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_x86-64_linux_Nightly_testList_0/236
jdk_util_1
java/util/concurrent/tck/JSR166TestCase.java#others

@pshipton
Copy link
Member Author

https://openj9-jenkins.osuosl.org/job/Test_openjdk17_j9_sanity.openjdk_aarch64_linux_Nightly_testList_1/321
jdk_util_0
java/util/concurrent/tck/JSR166TestCase.java#security-manager

@pshipton
Copy link
Member Author

pshipton commented Oct 25, 2024

@tajila @hzongaro this started failing every day.

@tajila
Copy link
Contributor

tajila commented Nov 1, 2024

@theresa-m Please take a look at this

@pshipton
Copy link
Member Author

pshipton commented Nov 5, 2024

@theresa-m
Copy link
Contributor

theresa-m commented Nov 11, 2024

I haven't been able to reproduce this running jdk_util in a grinder and the exception does not give any clues about the failure. I'm adding xdump options to the test commands to try to catch the next one and get more information. These should be reverted when this is resolved.
ibmruntimes/openj9-openjdk-jdk#881
ibmruntimes/openj9-openjdk-jdk23#76
ibmruntimes/openj9-openjdk-jdk21#226
ibmruntimes/openj9-openjdk-jdk17#414
ibmruntimes/openj9-openjdk-jdk11#846

@pshipton
Copy link
Member Author

pshipton commented Nov 27, 2024

@theresa-m A new failure but I don't see any dumps, the only file collected is verbosegc. The -Xdump option is there but looking again systhrow should likely be throw.

Some other thoughts:

  • looking at OpenJDK JSR166TestCase testDescendingIterator AssertionFailedError: expected: but was:  #14140, modify the -Xdump command to catch junit.framework.AssertionFailedError instead of the Exception at the end of the test, which may not help provide much detail about the failure
  • perhaps there is an option to override the default behavior where output is removed due to "Output overflow"
  • maybe it's worth modifying the test to record what failed and any details (or finding appropriate options), either to be printed at the end, or written to a file

https://openj9-jenkins.osuosl.org/job/Test_openjdk17_j9_sanity.openjdk_x86-64_linux_OMR_testList_0/131/
jdk_util_1
java/util/concurrent/tck/JSR166TestCase.java#others

    /home/jenkins/workspace/Test_openjdk17_j9_sanity.openjdk_x86-64_linux_OMR_testList_0/jdkbinary/j2sdk-image/bin/java \\
        -Dtest.vm.opts='-ea -esa -Xmx1540m -Xdump:system:none -Xdump:heap:none -Xdump:system:events=gpf+abort+traceassert+corruptcache -XX:-UseCompressedOops -Xverbosegclog' \\
        -Dtest.tool.vm.opts='-J-ea -J-esa -J-Xmx1540m -J-Xdump:system:none -J-Xdump:heap:none -J-Xdump:system:events=gpf+abort+traceassert+corruptcache -J-XX:-UseCompressedOops -J-Xverbosegclog' \\
        -Dtest.compiler.opts= \\
        -Dtest.java.opts= \\
        -Dtest.jdk=/home/jenkins/workspace/Test_openjdk17_j9_sanity.openjdk_x86-64_linux_OMR_testList_0/jdkbinary/j2sdk-image \\
        -Dcompile.jdk=/home/jenkins/workspace/Test_openjdk17_j9_sanity.openjdk_x86-64_linux_OMR_testList_0/jdkbinary/j2sdk-image \\
        -Dtest.timeout.factor=8.0 \\
        -Dtest.nativepath=/home/jenkins/workspace/Test_openjdk17_j9_sanity.openjdk_x86-64_linux_OMR_testList_0/jdkbinary/openjdk-test-image/jdk/jtreg/native \\
        -Dtest.root=/home/jenkins/workspace/Test_openjdk17_j9_sanity.openjdk_x86-64_linux_OMR_testList_0/aqa-tests/openjdk/openjdk-jdk/test/jdk \\
        -Dtest.name=java/util/concurrent/tck/JSR166TestCase.java#others \\
        -Dtest.file=/home/jenkins/workspace/Test_openjdk17_j9_sanity.openjdk_x86-64_linux_OMR_testList_0/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/util/concurrent/tck/JSR166TestCase.java \\
        -Dtest.src=/home/jenkins/workspace/Test_openjdk17_j9_sanity.openjdk_x86-64_linux_OMR_testList_0/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/util/concurrent/tck \\
        -Dtest.src.path=/home/jenkins/workspace/Test_openjdk17_j9_sanity.openjdk_x86-64_linux_OMR_testList_0/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/util/concurrent/tck \\
        -Dtest.classes=/home/jenkins/workspace/Test_openjdk17_j9_sanity.openjdk_x86-64_linux_OMR_testList_0/aqa-tests/TKG/output_17327075386992/jdk_util_1/work/classes/0/java/util/concurrent/tck/JSR166TestCase_others.d \\
        -Dtest.class.path=/home/jenkins/workspace/Test_openjdk17_j9_sanity.openjdk_x86-64_linux_OMR_testList_0/aqa-tests/TKG/output_17327075386992/jdk_util_1/work/classes/0/java/util/concurrent/tck/JSR166TestCase_others.d \\
        -Dtest.class.path.prefix=/home/jenkins/workspace/Test_openjdk17_j9_sanity.openjdk_x86-64_linux_OMR_testList_0/aqa-tests/TKG/output_17327075386992/jdk_util_1/work/classes/0/java/util/concurrent/tck/JSR166TestCase_others.d:/home/jenkins/workspace/Test_openjdk17_j9_sanity.openjdk_x86-64_linux_OMR_testList_0/aqa-tests/openjdk/openjdk-jdk/test/jdk/java/util/concurrent/tck \\
        -Dtest.modules=java.management \\
        --add-modules java.management \\
        -ea \\
        -esa \\
        -Xmx1540m \\
        -Xdump:system:none \\
        -Xdump:heap:none \\
        -Xdump:system:events=gpf+abort+traceassert+corruptcache \\
        -XX:-UseCompressedOops \\
        -Xverbosegclog \\
        -Djava.library.path=/home/jenkins/workspace/Test_openjdk17_j9_sanity.openjdk_x86-64_linux_OMR_testList_0/jdkbinary/openjdk-test-image/jdk/jtreg/native \\
        --add-opens java.base/java.util.concurrent=ALL-UNNAMED \\
        --add-opens java.base/java.lang=ALL-UNNAMED \\
        -Djsr166.testImplementationDetails=true \\
        -Xdump:system+java+snap:events=systhrow,filter=java/lang/Exception,msg_filter=*JUnit* \\
        com.sun.javatest.regtest.agent.MainWrapper /home/jenkins/workspace/Test_openjdk17_j9_sanity.openjdk_x86-64_linux_OMR_testList_0/aqa-tests/TKG/output_17327075386992/jdk_util_1/work/java/util/concurrent/tck/JSR166TestCase_others.d/junit.0.jta java/util/concurrent/tck/JSR166TestCase.java#others JSR166TestCase
result: Failed. Execution failed: `main' threw exception: java.lang.Exception: JUnit test failure

@theresa-m
Copy link
Contributor

theresa-m commented Nov 28, 2024

Thanks @pshipton, I created a new pr to correct my xdump method and catch AssertionFailedError as well. I modified the TestRunner to make the output more verbose, hopefully this will help give a better idea of which test within Jsr166TestCase is failing. ibmruntimes/openj9-openjdk-jdk#898

perhaps there is an option to override the default behavior where output is removed due to "Output overflow"

I believe this change would need to be made in https://github.com/adoptium/aqa-tests or EXTRA_OPTIONS in a grinder. I can try a grinder run again and see if anything turns up.

@theresa-m
Copy link
Contributor

I haven't been able to reproduce this running jdk_util in a grinder and the exception does not give any clues about the failure. I'm adding xdump options to the test commands to try to catch the next one and get more information. These should be reverted when this is resolved. ibmruntimes/openj9-openjdk-jdk#881 ibmruntimes/openj9-openjdk-jdk23#76 ibmruntimes/openj9-openjdk-jdk21#226 ibmruntimes/openj9-openjdk-jdk17#414 ibmruntimes/openj9-openjdk-jdk11#846

These have been added as well:
ibmruntimes/openj9-openjdk-jdk#898
ibmruntimes/openj9-openjdk-jdk23#82
ibmruntimes/openj9-openjdk-jdk21#231
ibmruntimes/openj9-openjdk-jdk17#418
ibmruntimes/openj9-openjdk-jdk11#850

@pshipton
Copy link
Member Author

pshipton commented Dec 9, 2024

https://openj9-jenkins.osuosl.org/job/Test_openjdk17_j9_sanity.openjdk_aarch64_linux_OMR_testList_2/200 - cent9-aarch64-2
jdk_util_1
java/util/concurrent/tck/JSR166TestCase.java#security-manager

https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Test/Test_openjdk17_j9_sanity.openjdk_aarch64_linux_OMR_testList_2/200/openjdk_test_output.tar.gz

@theresa-m we got diagnostics for an AssertionFailedError, 6 of them.

@theresa-m
Copy link
Contributor

The javacore file shows that the failure is due to a timeout in LockSupportTest.java.testParkNeg_parkUntil which calls jdk.internal.misc.Unafe.park().

"junit/framework/AssertionFailedError" "timed out waiting for thread to terminate, thread=Thread[Thread-361,5,MainThreadGroup], state=TIMED_WAITING" received
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at junit/framework/Assert.fail(Assert.java:57)
4XESTACKTRACE                at junit/framework/TestCase.fail(TestCase.java:223)
4XESTACKTRACE                at JSR166TestCase.threadFail(JSR166TestCase.java:920)
4XESTACKTRACE                at JSR166TestCase.awaitTermination(JSR166TestCase.java:1688)
4XESTACKTRACE                at JSR166TestCase.awaitTermination(JSR166TestCase.java:1702)
4XESTACKTRACE                at LockSupportTest.testParkNeg(LockSupportTest.java:403)
4XESTACKTRACE                at LockSupportTest.testParkNeg_parkUntil(LockSupportTest.java:389)
4XESTACKTRACE                at jdk/internal/reflect/NativeMethodAccessorImpl.invoke0(Native Method)
4XESTACKTRACE                at jdk/internal/reflect/NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77(Compiled Code))
4XESTACKTRACE                at jdk/internal/reflect/DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43(Compiled Code))
4XESTACKTRACE                at java/lang/reflect/Method.invoke(Method.java:575(Compiled Code))
4XESTACKTRACE                at junit/framework/TestCase.runTest(TestCase.java:177(Compiled Code))
4XESTACKTRACE                at JSR166TestCase.runTest(JSR166TestCase.java:419(Compiled Code))
4XESTACKTRACE                at junit/framework/TestCase.runBare(TestCase.java:142(Compiled Code))
4XESTACKTRACE                at JSR166TestCase.runBare(JSR166TestCase.java:410(Compiled Code))
4XESTACKTRACE                at junit/framework/TestResult$1.protect(TestResult.java:122(Compiled Code))
4XESTACKTRACE                at junit/framework/TestResult.runProtected(TestResult.java:142(Compiled Code))
4XESTACKTRACE                at junit/framework/TestResult.run(TestResult.java:125(Compiled Code))
4XESTACKTRACE                at junit/framework/TestCase.run(TestCase.java:130(Compiled Code))
4XESTACKTRACE                at junit/framework/TestSuite.runTest(TestSuite.java:241(Compiled Code))
4XESTACKTRACE                at junit/framework/TestSuite.run(TestSuite.java:236(Compiled Code))
4XESTACKTRACE                at junit/framework/TestSuite.runTest(TestSuite.java:241)
4XESTACKTRACE                at junit/framework/TestSuite.run(TestSuite.java:236)

I will continue to investigate what might have caused this.

@theresa-m
Copy link
Contributor

theresa-m commented Dec 10, 2024

I think the error is due to an overflow when calculating millis = timeout - timeNow;.
https://github.com/eclipse-openj9/openj9/blob/master/runtime/vm/threadpark.cpp#L56-L62

For this test millis should be negative and the result set to J9THREAD_TIMED_OUT but I can see that thread 361 enters omrthread_park.

The input for this test is a negative number that is close to the minimum value of a long (System.currentTimeMillis() + Long.MIN_VALUE + 1).

If timeNow is greater than System.currentTimeMillis() + 1 millis will go beyond its minimum value and return a large positive number which will park the thread for a long time and the test will time out.

J9THREAD_TIMED_OUT should be set if millis <= 0 but also if timeout <= 0

@JasonFengJ9
Copy link
Member

openjdk21_j9_sanity.openjdk_ppc64le_linux(ubu20le-rtp-rt11-1)

[2024-12-17T18:16:49.552Z] variation: -Xdump:system:none -Xdump:heap:none -Xdump:system:events=gpf+abort+traceassert+corruptcache Mode650
[2024-12-17T18:16:49.553Z] JVM_OPTIONS:  -Xdump:system:none -Xdump:heap:none -Xdump:system:events=gpf+abort+traceassert+corruptcache -XX:-UseCompressedOops -Xverbosegclog 

[2024-12-17T18:26:01.475Z] TEST: java/util/concurrent/tck/JSR166TestCase.java#security-manager

[2024-12-17T18:26:01.554Z] TEST RESULT: Failed. Execution failed: `main' threw exception: java.lang.Exception: JUnit test failure
[2024-12-17T18:26:01.554Z] --------------------------------------------------
[2024-12-17T18:49:00.383Z] Test results: passed: 949; failed: 1
[2024-12-17T18:49:32.066Z] Report written to /home/jenkins/workspace/Test_openjdk21_j9_sanity.openjdk_ppc64le_linux_testList_0/aqa-tests/TKG/output_17344534993180/jdk_util_1/report/html/report.html
[2024-12-17T18:49:32.067Z] Results written to /home/jenkins/workspace/Test_openjdk21_j9_sanity.openjdk_ppc64le_linux_testList_0/aqa-tests/TKG/output_17344534993180/jdk_util_1/work
[2024-12-17T18:49:32.067Z] Error: Some tests failed or other problems occurred.
[2024-12-17T18:49:32.067Z] -----------------------------------
[2024-12-17T18:49:32.067Z] jdk_util_1_FAILED

@theresa-m
Copy link
Contributor

#20802 has been merged. I will leave this issue open for a few weeks to be sure this failure doesn't show up again.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

5 participants