OpenJDK java/lang/Thread/SleepSanity Duration 999ms, expected >= 1000ms

[pshipton]

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_x86-64_windows_Nightly/1

jdk_lang_0, jdk_lang_j9_0 (passed in jdk_lang_1)
java/lang/Thread/SleepSanity.java

04:51:09  STARTED    SleepSanity::testMillisNanos 'testMillisNanos()'
04:51:09  SUCCESSFUL SleepSanity::testMillisNanos 'testMillisNanos()'
04:51:09  STARTED    SleepSanity::testMillis 'testMillis()'
04:51:09  org.opentest4j.AssertionFailedError: Duration 999ms, expected >= 1000ms ==> expected: <true> but was: <false>
04:51:09  	at org.junit.jupiter.api.AssertionFailureBuilder.build(AssertionFailureBuilder.java:151)
04:51:09  	at org.junit.jupiter.api.AssertionFailureBuilder.buildAndThrow(AssertionFailureBuilder.java:132)
04:51:09  	at org.junit.jupiter.api.AssertTrue.failNotTrue(AssertTrue.java:63)
04:51:09  	at org.junit.jupiter.api.AssertTrue.assertTrue(AssertTrue.java:36)
04:51:09  	at org.junit.jupiter.api.Assertions.assertTrue(Assertions.java:211)
04:51:09  	at SleepSanity.testTimes(SleepSanity.java:80)
04:51:09  	at SleepSanity.testMillis(SleepSanity.java:48)

[pshipton]

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_x86-64_windows_Nightly/2/

[keithc-ca]

This is a new test, not a new problem. I reproduced the failure in

>java -version
openjdk version "17.0.7" 2023-04-18
IBM Semeru Runtime Open Edition 17.0.7.0 (build 17.0.7+7)
Eclipse OpenJ9 VM 17.0.7.0 (build openj9-0.38.0, JRE 17 Windows 10 amd64-64-Bit Compressed References 20230418_439 (JIT enabled, AOT enabled)
OpenJ9   - d57d05932
OMR      - 855813495
JCL      - 9d7a231edbc based on jdk-17.0.7+7)

[keithc-ca]

And also in

openjdk version "1.8.0_322"
IBM Semeru Runtime Open Edition (build 1.8.0_322-b06)
Eclipse OpenJ9 VM (build openj9-0.30.0, JRE 1.8.0 Windows 10 amd64-64-Bit Compressed References 20220128_311 (JIT enabled, AOT enabled)
OpenJ9   - 9dccbe076
OMR      - dac962a28
JCL      - c1d9a7af7c based on jdk8u322-b06)

fail: Duration 99ms, expected >= 100ms

[keithc-ca]

I think the problem is in thrdsup.h for Windows.

That code computes how long the thread has waited by comparing the results of two calls to GetTickCount(). If we're unlucky, a tick can occur immediately after the first call effectively reducing those measurements by almost the tick resolution which Microsoft says is "typically in the range of 10 milliseconds to 16 milliseconds" (see [1]). I think it should be modified to use omrtime_hires_clock() and omrtime_hires_frequency() which would reduce measurement errors to less than a microsecond.

[1] https://learn.microsoft.com/en-us/windows/win32/api/sysinfoapi/nf-sysinfoapi-gettickcount

[keithc-ca]

The test fails in hotspot VMs as well:

openjdk version "1.8.0_372"
OpenJDK Runtime Environment (Temurin)(build 1.8.0_372-b07)
OpenJDK 64-Bit Server VM (Temurin)(build 25.372-b07, mixed mode)

fail: Duration 99ms (99,909,600ns), expected >= 100ms

[pshipton]

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_x86-64_mac_OMR_testList_1/104/
jdk_lang_1
java/lang/Thread/SleepSanity.java

09:26:02  STARTED    SleepSanity::testMillisNanos 'testMillisNanos()'
09:26:02  org.opentest4j.AssertionFailedError: Exited before timeout
09:26:02  	at org.junit.jupiter.api.AssertionUtils.fail(AssertionUtils.java:38)
09:26:02  	at org.junit.jupiter.api.Assertions.fail(Assertions.java:135)
09:26:02  	at SleepSanity.testTimeout(SleepSanity.java:98)
09:26:02  	at SleepSanity.testMillisNanos(SleepSanity.java:64)
...
09:26:02  FAILED     SleepSanity::testMillisNanos 'testMillisNanos()'

[keithc-ca]

So macOS too? I have (had?) some work-in-progress to address this problem on Windows, but it got put on the back burner because it never seemed like a significant problem in practice. Does anyone disagree?

[pshipton]

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_s390x_linux_Nightly_testList_0/351