search

eclipse-openj9 / openj9

Eclipse OpenJ9: A Java Virtual Machine for OpenJDK that's optimized for small footprint, fast start-up, and high throughput. Builds on Eclipse OMR (https://github.com/eclipse/omr) and combines with the Extensions for OpenJDK for OpenJ9 repo.
Other
3.28k stars 722 forks source link

[win_x86] SE80_GIT cmdLineTest_J9test_elapsedTime_0 FAILED: testElapsedTime() sleep 100ms elapsedNanoTimeInMillis (98ms) should NOT be less than minElapsedNanoTimeInMillis (100ms) & FAILED: testElapsedTime() timer delayed 2s elapsedNanoTimeInMillis (1993ms) should NOT be less than minElapsedNanoTimeInMillis (2000ms) #18487

Open JasonFengJ9 opened 11 months ago

JasonFengJ9 commented 11 months ago

Failure link

From an internal build(win10x64rtp-3-1):

java version "1.8.0_391"
Java(TM) SE Runtime Environment (build 8.0.9.0 - pwi3280sr9-20231020_01(SR9))
IBM J9 VM (build 2.9, JRE 1.8.0 Windows 10 x86-32-Bit 20231120_60964 (JIT enabled, AOT enabled)
OpenJ9   - 002b68f
OMR      - fdf5b01
IBM      - 7394519)
JCL - 20231012_01 based on Oracle jdk8u391-b13

Optional info

Failure output (captured from console output)

*** Starting test suite: Elapsed time measurement ***
Testing: Verify the elapsed time
Test start time: 2023/11/20 05:50:26 Eastern Standard Time
Running command: "w:\builds\bld_60964/sdk/wi3280\bin\java"   -cp "w:\builds\bld_60964/jvmtest/test/SE80\TKG\lib\testng.jar;w:\builds\bld_60964/jvmtest/test/SE80\TKG\lib\jcommander.jar;w:\builds\bld_60964/jvmtest/test/SE80\functional\cmdLineTests\cmdLineTest_J9tests\cmdLineTest_J9tests.jar" ElapsedTime
Time spent starting: 31 milliseconds
Time spent executing: 1531 milliseconds
Test result: FAILED
Output from test:
 [OUT] testElapsedTime() sleep 100ms checkElapseTime starts, current thread name: main, Mon Nov 20 05:50:27 EST 2023, System.currentTimeMillis() 1700477427809, System.nanoTime() 360373632850970
 [OUT] testElapsedTime() sleep 100ms: startMillisTime (1700477427637ms) startNanoTime (360373463770770ns) currentMillisTime (1700477427747ms) currentNanoTime (360373561620110ns) elapsedMillisTime (110ms) elapsedNanoTime (97849340ns)
 [OUT] FAILED: testElapsedTime() sleep 100ms elapsedNanoTimeInMillis (98ms) should NOT be less than minElapsedNanoTimeInMillis (100ms)
 [OUT] testElapsedTime() sleep 100ms checkElapseTime ends, current thread name: main, Mon Nov 20 05:50:27 EST 2023, System.currentTimeMillis() 1700477427809, System.nanoTime() 360373634005360
 [ERR] Exception in thread "main" java.lang.AssertionError: 
 [ERR] at org.testng.AssertJUnit.fail(AssertJUnit.java:59)
 [ERR] at org.testng.AssertJUnit.assertTrue(AssertJUnit.java:24)
 [ERR] at org.testng.AssertJUnit.assertTrue(AssertJUnit.java:33)
 [ERR] at ElapsedTime.testElapsedTime(ElapsedTime.java:43)
 [ERR] at ElapsedTime.main(ElapsedTime.java:32)
>> Success condition was not found: [Output match: Thread-0]
>> Success condition was not found: [Output match: PASSED: testElapsedTime]
>> Failure condition was found: [Output match: FAILED: testElapsedTime]

---TEST RESULTS---
Number of PASSED tests: 0 out of 1
Number of FAILED tests: 1 out of 1

---SUMMARY OF FAILED TESTS---
Verify the elapsed time

10x internal grinder

JasonFengJ9 commented 11 months ago

JDK8 win_x86

*** Starting test suite: Elapsed time measurement ***
Testing: Verify the elapsed time
Test start time: 2023/11/19 19:28:25 Pacific Standard Time
Running command: "C:/Users/jenkins/workspace/Grinder/jdkbinary/j2sdk-image\\bin\\java"  -Xtrace:print=mt,methods=java/lang/System.currentTimeMillis -cp "C:/Users/jenkins/workspace/Grinder/aqa-tests/\TKG\lib\testng.jar;C:/Users/jenkins/workspace/Grinder/aqa-tests/\TKG\lib\jcommander.jar;C:/Users/jenkins/workspace/Grinder/aqa-tests///..//jvmtest\functional\cmdLineTests\cmdLineTest_J9tests\cmdLineTest_J9tests.jar" ElapsedTime
Time spent starting: 47 milliseconds
Time spent executing: 4125 milliseconds
Test result: FAILED
Output from test:
 [OUT] testElapsedTime() sleep 100ms checkElapseTime starts, current thread name: main, Sun Nov 19 19:28:27 PST 2023, System.currentTimeMillis() 1700450907833, System.nanoTime() 2065298880175520
 [OUT] testElapsedTime() sleep 100ms: startMillisTime (1700450907614ms) startNanoTime (2065298661913140ns) currentMillisTime (1700450907724ms) currentNanoTime (2065298761708770ns) elapsedMillisTime (110ms) elapsedNanoTime (99795630ns)
 [OUT] testElapsedTime() sleep 100ms checkElapseTime ends, current thread name: main, Sun Nov 19 19:28:27 PST 2023, System.currentTimeMillis() 1700450907833, System.nanoTime() 2065298881778780
 [OUT] getResultAndCancelTimers before Thread.yield() taskRunning = 2, current thread name: main, Sun Nov 19 19:28:27 PST 2023, System.currentTimeMillis() 1700450907849, System.nanoTime() 2065298895998750
 [OUT] testElapsedTime() timer delayed 100ms checkElapseTime starts, current thread name: testElapsedTime() timer delayed 100ms, Sun Nov 19 19:28:27 PST 2023, System.currentTimeMillis() 1700450907958, System.nanoTime() 2065298996553990
 [OUT] testElapsedTime() timer delayed 100ms: startMillisTime (1700450907849ms) startNanoTime (2065298889757670ns) currentMillisTime (1700450907958ms) currentNanoTime (2065298996174240ns) elapsedMillisTime (109ms) elapsedNanoTime (106416570ns)
 [OUT] testElapsedTime() timer delayed 100ms checkElapseTime ends, current thread name: testElapsedTime() timer delayed 100ms, Sun Nov 19 19:28:27 PST 2023, System.currentTimeMillis() 1700450907958, System.nanoTime() 2065298998616360
 [OUT] testElapsedTime() timer delayed 2s checkElapseTime starts, current thread name: testElapsedTime() timer delayed 2s, Sun Nov 19 19:28:29 PST 2023, System.currentTimeMillis() 1700450909849, System.nanoTime() 2065300887216350
 [OUT] testElapsedTime() timer delayed 2s: startMillisTime (1700450907849ms) startNanoTime (2065298894223580ns) currentMillisTime (1700450909849ms) currentNanoTime (2065300886764230ns) elapsedMillisTime (2000ms) elapsedNanoTime (1992540650ns)
 [OUT] FAILED: testElapsedTime() timer delayed 2s elapsedNanoTimeInMillis (1993ms) should NOT be less than minElapsedNanoTimeInMillis (2000ms)
keithc-ca commented 11 months ago

This seems like a duplicate of https://github.com/eclipse-openj9/openj9/issues/17638.

JasonFengJ9 commented 11 months ago

This seems like a duplicate of https://github.com/eclipse-openj9/openj9/issues/17638.

Okay, so this seems an existing problem, also for RI.

keithc-ca commented 11 months ago

also for RI

Sort of, I suppose. The test is new for Java 21; it was Temurin Java 8 that failed.

pshipton commented 11 months ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk17_j9_sanity.functional_ppc64_aix_Nightly_testList_1/586 cmdLineTest_J9test_elapsedTime_0

Testing: Verify the elapsed time
Test start time: 2023/11/25 03:44:17 Coordinated Universal Time
Running command: "/home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64_aix_Nightly_testList_1/jdkbinary/j2sdk-image/bin/java"   -cp "/home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64_aix_Nightly_testList_1/aqa-tests/TKG/../TKG/lib/testng.jar:/home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64_aix_Nightly_testList_1/aqa-tests/TKG/../TKG/lib/jcommander.jar:/home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64_aix_Nightly_testList_1/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/cmdLineTest_J9tests/cmdLineTest_J9tests.jar" ElapsedTime
Time spent starting: 88 milliseconds
Time spent executing: 2481 milliseconds
Test result: FAILED
Output from test:
 [OUT] testElapsedTime() sleep 100ms checkElapseTime starts, current thread name: main, Sat Nov 25 03:44:19 UTC 2023, System.currentTimeMillis() 1700883859024, System.nanoTime() 36073780486482341
 [OUT] testElapsedTime() sleep 100ms: startMillisTime (1700883857712ms) startNanoTime (36073779174622029ns) currentMillisTime (1700883858749ms) currentNanoTime (36073780253957648ns) elapsedMillisTime (1037ms) elapsedNanoTime (1079335619ns)
 [OUT] FAILED: testElapsedTime() sleep 100ms elapsedMillisTime (1037ms) should NOT be greater than maxElapsedMillisTime (800ms)
 [OUT] FAILED: testElapsedTime() sleep 100ms elapsedNanoTimeInMillis (1080ms) should NOT be greater than maxElapsedNanoTimeInMillis (800ms)
 [OUT] testElapsedTime() sleep 100ms checkElapseTime ends, current thread name: main, Sat Nov 25 03:44:19 UTC 2023, System.currentTimeMillis() 1700883859755, System.nanoTime() 36073781216721349
 [ERR] Exception in thread "main" java.lang.AssertionError: 
 [ERR]  at org.testng.AssertJUnit.fail(AssertJUnit.java:59)
 [ERR]  at org.testng.AssertJUnit.assertTrue(AssertJUnit.java:24)
 [ERR]  at org.testng.AssertJUnit.assertTrue(AssertJUnit.java:33)
 [ERR]  at ElapsedTime.testElapsedTime(ElapsedTime.java:43)
 [ERR]  at ElapsedTime.main(ElapsedTime.java:32)
>> Success condition was not found: [Output match: Thread-0]
>> Success condition was not found: [Output match: PASSED: testElapsedTime]
>> Failure condition was found: [Output match: FAILED: testElapsedTime]