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.23k stars 711 forks source link

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

Open pshipton opened 1 year ago

pshipton commented 1 year ago

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 commented 1 year ago

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

keithc-ca commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 12 months ago

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