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

Random performance dropouts during parallel execution

XMLWordPrintable

    • generic
    • generic

      FULL PRODUCT VERSION :
      Java(TM) SE Runtime Environment (build 1.8.0_92)
      Java(TM) SE Runtime Environment (build 1.8.0_121)

      FULL OS VERSION :
      Windows 10 professional Version 10.0.14393 Build 14393
      Linux 2.6.32-358.11.1.el6.x86_64 #1 SMP Wed Jun 12 03:34:52 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux

      A DESCRIPTION OF THE PROBLEM :
      When running the attached source code we experience random performance dropouts.

      Running the same code snippet on jre-7, or with "-Xint" flag or inlining the "gradient" method, fixed the problem.

      Also we found out that the overall runtime of our code went up by a factor of 4 when switching from JRE-7 to JRE-8. Any explanation for this?


      THE PROBLEM WAS REPRODUCIBLE WITH -Xint FLAG: No

      THE PROBLEM WAS REPRODUCIBLE WITH -server FLAG: Yes

      REGRESSION. Last worked in version 7u76

      STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
      Run the attached code on JRE-8 and inspect the output.

      EXPECTED VERSUS ACTUAL BEHAVIOR :
      There should be no performance drop on any of the threads running in parallel. In particular the numerical computation should not influence the Logger thread in out example.
      ERROR MESSAGES/STACK TRACES THAT OCCUR :
      Instead we observe this output:

      Start
      ........
      -> levels took: 2.2 sec.
      ...........................
      -> levels took: 6.6 sec.
      ............................................
      -> levels took: 11.0 sec.
      ..................................
      -> levels took: 8.3 sec.
      ..................
      -> levels took: 10.7 sec.

      Log-131 took: 6.3 sec., expected 250 ms.
      ....
      -> levels took: 13.1 sec.

      Log-136 took: 12.1 sec., expected 250 ms.
      ........................................................
      Log-193 took: 1.5 sec., expected 250 ms.

      -> levels took: 15.5 sec.
      ....
      Log-198 took: 16.9 sec., expected 250 ms.
      -> levels took: 17.9 sec.

      ............
      Log-211 took: 17.3 sec., expected 250 ms.
      -> levels took: 20.3 sec.

      ...........................................................................................
      -> levels took: 22.7 sec.
      .........................................................
      -> levels took: 25.1 sec.
      Log-360 took: 10.8 sec., expected 250 ms.
      ..............................................................................................................
      -> levels took: 27.4 sec.


      REPRODUCIBILITY :
      This bug can be reproduced always.

      ---------- BEGIN SOURCE ----------
      /**
       * @author Marc Flesch
       */
      public class MSSTest {

      public static void main(String[] args) {
      submit(new MSS(), "MSS");
      submit(new BusyLog(250), "Log");
      }

      private static void submit(Runnable r, String name) { new Thread(r, name).start();}
      private static String dt(long t1, long t2) { return ((t2 - t1) / 100) / 10.0 + " sec."; }

      private static final class BusyLog implements Runnable {
      private final long timeout;

      BusyLog(long timeout) {
      this.timeout = timeout;
      }

      @Override
      public void run() {
      int counter = -1;
      while (true) {
      long t1 = System.currentTimeMillis();
      while(System.currentTimeMillis() - t1 < timeout) {
      Math.log(Float.NaN);
      }
      long t2 = System.currentTimeMillis();
      counter++;
      String dt = dt(t1, t2);
      if (dt.equals(dt(0, timeout))) {
      System.out.print(".");
      } else {
      System.err.println("\nLog-" + counter + " took: " + dt + ", expected " + timeout + " ms.");
      }
      }
      }
      }

      private static class MSS implements Runnable {

      public void run() {
      System.out.println("Start");
      int binCount = 2000000;
      float mean = 0.76f;
      float sigma = 0.75f;
      float[] levels = new float[binCount];

      for (int binWindow = 2; binWindow < 64; binWindow+=4) {
      int n = levels.length;
      float[] gradient = new float[n];
      float inv2BinWidth = 1f / (binWindow * binWindow);
      float mean4 = mean / 4;
      float sigma2 = 4 / (sigma * sigma);
      float ms2 = mean / (sigma * sigma);
      int window = 3 * binWindow;
      float[] exponents = new float[window + 1];
      for (int i = 0; i <= window; i++) {
      exponents[i] = (float) (i * Math.exp(-0.5 * i * i * inv2BinWidth));
      }
      long t1 = System.currentTimeMillis();
      gradient(levels, n, gradient, mean4, sigma2, ms2, window, exponents);
      long t2 = System.currentTimeMillis();
      System.out.println("\n-> levels took: " + dt(t1, t2));
      }
      System.err.println("Done.");
      System.exit(0);
      }

      private void gradient(float[] levels, int n, float[] gradient, float mean4, float sigma2, float ms2, int window, float[] exponents) {
      for (int i = 0; i < n; i++) {
      float invB;
      int d = 0;
      if (levels[i] < mean4) {
      invB = sigma2;
      } else {
      invB = ms2 / levels[i];
      }
      for (int j = i + 1; j < n; j++) {
      d++;
      float inv_i;
      if (levels[j] < mean4) {
      inv_i = sigma2;
      } else {
      inv_i = ms2 / levels[j];
      }
      float r = levels[j] - levels[i];
      float val = -0.5f * r * r;
      gradient[i] += exponents[d] * Math.exp(val * invB);
      gradient[j] -= exponents[d] * Math.exp(val * inv_i);
      if (d == window) {
      break;
      }
      }
      }
      }
      }
      }

      ---------- END SOURCE ----------

      CUSTOMER SUBMITTED WORKAROUND :
      If you could provide a work around for us that would be great. Thanks.

            thartmann Tobias Hartmann
            webbuggrp Webbug Group
            Votes:
            0 Vote for this issue
            Watchers:
            6 Start watching this issue

              Created:
              Updated:
              Resolved: