JDK-8252200 : Thread::sleep(1) time is longer than 1ms in Java 14 on Windows 10
  • Type: Bug
  • Component: hotspot
  • Sub-Component: runtime
  • Affected Version: 8,13,14,15
  • Priority: P3
  • Status: Closed
  • Resolution: Not an Issue
  • OS: windows_10
  • CPU: x86_64
  • Submitted: 2020-08-20
  • Updated: 2020-10-16
  • Resolved: 2020-08-27
Related Reports
Relates :  
Description
ADDITIONAL SYSTEM INFORMATION :
Platform:
Windows 10 [Version 10.0.19041.450]
Ryzen 3900x, 32GB RAM

Runtimes:
+ Oracle JDK 1.8
+ OpenJDK 9.0.4
+ OpenJDK 10
+ Zulu 11 / 12 / 13
-  Zulu 14 / 15-EA


A DESCRIPTION OF THE PROBLEM :
This program
-------------------------------------------------
public class uu {
  public static void main(String[] args) throws Throwable {
    long t0 = System.nanoTime();
    Thread.sleep(1);
    System.out.println(System.nanoTime()-t0);
  }
}
-------------------------------------------------

is expected to typically print values of 1ms when run on an otherwise idle system. On Java 13 this was true in >70% of the cases. On Java 14 >80% of the cases report 2ms or higher, and the higher percentiles are noticeably worse.

Percentile chart JDK13: https://ibb.co/Y85DVjC
Percentile chart JDK14: https://ibb.co/jfwj8L4


The below code generates a printout of percentiles
-------------------------------------------------
public class uu {
  public static void main(String[] args) throws Throwable {
    final int n = 10000;

    // sleep for 1ms
    final long[] time = new long[n + 1];
    for (int i = 0; i < time.length; i++) {
        time[i] = System.nanoTime();
        Thread.sleep(1);
    }

    // create sorted time deltas
    final long[] dt = new long[time.length - 1];
    for (int i = 0; i < dt.length; i++) {
        dt[i] = time[i + 1] - time[i];
    }
    Arrays.sort(dt);

    // print percentiles
    final double nsToMs = 1E-6;
    System.out.println(String.format("10    : %.1f ms", dt[(int) (dt.length * 0.100)] * nsToMs));
    System.out.println(String.format("30    : %.1f ms", dt[(int) (dt.length * 0.300)] * nsToMs));
    System.out.println(String.format("50    : %.1f ms", dt[(int) (dt.length * 0.500)] * nsToMs));
    System.out.println(String.format("70    : %.1f ms", dt[(int) (dt.length * 0.700)] * nsToMs));
    System.out.println(String.format("90    : %.1f ms", dt[(int) (dt.length * 0.900)] * nsToMs));
    System.out.println(String.format("95    : %.1f ms", dt[(int) (dt.length * 0.950)] * nsToMs));
    System.out.println(String.format("99    : %.1f ms", dt[(int) (dt.length * 0.990)] * nsToMs));
    System.out.println(String.format("99.9  : %.1f ms", dt[(int) (dt.length * 0.999)] * nsToMs));
    System.out.println(String.format("99.99 : %.1f ms", dt[(int) (dt.length * 0.9999)] * nsToMs));
    System.out.println(String.format("Total runtime: %.1f s", (time[n] - time[0]) * 1E-9));

  }
}
-------------------------------------------------

REGRESSION : Last worked in version 13

STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
Call Thread.sleep(1) on an idle system and measure the elapsed time (see code example)

EXPECTED VERSUS ACTUAL BEHAVIOR :
EXPECTED -
== zulu-13.0.3 ==
10    : 1.0 ms
30    : 1.0 ms
50    : 1.0 ms
70    : 2.0 ms
90    : 2.0 ms
95    : 2.0 ms
99    : 2.2 ms
99.9  : 2.3 ms
99.99 : 3.1 ms
Total runtime: 14.1 s
ACTUAL -
== zulu-14.0.1 ==
10    : 1.0 ms
30    : 2.0 ms
50    : 2.0 ms
70    : 2.8 ms
90    : 3.0 ms
95    : 3.3 ms
99    : 4.0 ms
99.9  : 5.0 ms
99.99 : 6.0 ms
Total runtime: 21.4 s

---------- BEGIN SOURCE ----------
public class uu {
  public static void main(String[] args) throws Throwable {
    final int n = 10000;

    // sleep for 1ms
    final long[] time = new long[n + 1];
    for (int i = 0; i < time.length; i++) {
        time[i] = System.nanoTime();
        Thread.sleep(1);
    }

    // create sorted time deltas
    final long[] dt = new long[time.length - 1];
    for (int i = 0; i < dt.length; i++) {
        dt[i] = time[i + 1] - time[i];
    }
    Arrays.sort(dt);

    // print percentiles
    final double nsToMs = 1E-6;
    System.out.println(String.format("10    : %.1f ms", dt[(int) (dt.length * 0.100)] * nsToMs));
    System.out.println(String.format("30    : %.1f ms", dt[(int) (dt.length * 0.300)] * nsToMs));
    System.out.println(String.format("50    : %.1f ms", dt[(int) (dt.length * 0.500)] * nsToMs));
    System.out.println(String.format("70    : %.1f ms", dt[(int) (dt.length * 0.700)] * nsToMs));
    System.out.println(String.format("90    : %.1f ms", dt[(int) (dt.length * 0.900)] * nsToMs));
    System.out.println(String.format("95    : %.1f ms", dt[(int) (dt.length * 0.950)] * nsToMs));
    System.out.println(String.format("99    : %.1f ms", dt[(int) (dt.length * 0.990)] * nsToMs));
    System.out.println(String.format("99.9  : %.1f ms", dt[(int) (dt.length * 0.999)] * nsToMs));
    System.out.println(String.format("99.99 : %.1f ms", dt[(int) (dt.length * 0.9999)] * nsToMs));
    System.out.println(String.format("Total runtime: %.1f s", (time[n] - time[0]) * 1E-9));

  }
}
---------- END SOURCE ----------

CUSTOMER SUBMITTED WORKAROUND :
None. LockSupport::parkNanos on JDK14 fares comparably to JDK13, but there was a regression from Windows build 18362 to 19041 that makes it significantly worse than sleep.

FREQUENCY : always



Comments
I think the observed behaviour is a combination of two things: First, in JDK 14 we fixed JDK-6313903 whereby sleep could return early. By ensuring it can never return early we sometimes induce an extra sleep of 1 "tick" (nominally 1ms but it depends on hardware). So on JDK 13 where we can return early the results are skewed to showing short sleep times with fewer sleeps much over 1ms; whereas in later releases we will see results mostly in the 1-2ms range. Second the outliers are an artifact of the way the test code has been written. The long we loop the more likely there will be some external interference (thread scheduling, system interrupts or other load) that causes what appears to be a long sleep. My own results don't show a huge difference and worse outliers can be seen in JDK 13 e.g.: $ java13 SleepTime 10 : 1.0 ms 30 : 1.4 ms 50 : 2.0 ms 70 : 2.0 ms 90 : 2.0 ms 95 : 2.1 ms 99 : 2.2 ms 99.9 : 2.4 ms 99.99 : 5.5 ms Total runtime: 17.0 s $ java14 SleepTime 10 : 1.0 ms 30 : 1.8 ms 50 : 2.0 ms 70 : 2.0 ms 90 : 2.2 ms 95 : 3.0 ms 99 : 3.0 ms 99.9 : 4.0 ms 99.99 : 4.6 ms Total runtime: 18.4 s Please see JDK-6313903 for more detailed information about the high variance seen with sleep times on Windows. Closing as "Not an issue"
27-08-2020

As the specification for Thread.sleep states: "Causes the currently executing thread to sleep (temporarily cease execution) for the specified number of milliseconds, *subject to the precision and accuracy of system timers and schedulers*." So the actual minimum sleep time depends on the resolution of the underlying operating system timed-wait mechanisms. The reporter states: "On Java 13 this was true in >70% of the cases. On Java 14 >80% of the cases report 2ms or higher, and the higher percentiles are noticeably worse. " suggesting a change in behaviour in JDK 14. There was a change in behaviour in JDK 14 introduced by JDK-8230423, prior to that change we would check to see if the timeout had elapsed before doing an actual park, so if the code was exceptionally slow or the thread was rescheduled then it might be possible to see 1ms has already elapsed and so skip the park. After that fix we always call park and so are always subject to the minimum blocking time of the OS. However the chances of seeing the 1ms elapse before calling park should be extremely low - the code simply checks the interrupt state of the thread. Further investigation in progress.
26-08-2020

The observations on Windows 10: JDK 8: Fail JDK 13: Fail JDK 14: Fail JDK 15: Fail This incident is not a regression because most of test results of JDK 13 are >1ms.
24-08-2020