Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-8252200

Thread::sleep(1) time is longer than 1ms in Java 14 on Windows 10

XMLWordPrintable

    • x86_64
    • windows_10

      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


            dholmes David Holmes
            webbuggrp Webbug Group
            Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

              Created:
              Updated:
              Resolved: