Ejemplo n.º 1
0
  /**
   * Acquires a permit from this instance, blocking until the request can be granted.
   *
   * @throws InterruptedException
   */
  public void acquire() throws InterruptedException {
    lock.lock();
    try {
      // logger.info("avail: " + availables.availablePermits());

      availables.acquire();
      long target = getTargetTime(acquiredPermits++); // set to beginning of time period
      if (System.nanoTime() > target) return;

      TimeUnit.NANOSECONDS.sleep(target - System.nanoTime());
    } finally {
      lock.unlock();
    }
  }
Ejemplo n.º 2
0
 /**
  * Idle sleep.
  *
  * @return <code>true</code> if continue, <code>false</code> if interrupted.
  */
 protected final boolean idleSleep() {
   idleCount++;
   // sleep
   try {
     final long nanoBeforeIdle = System.nanoTime();
     // use nanoseconds for performance
     TimeUnit.NANOSECONDS.sleep(idleSleepNano);
     idleTimeCost += System.nanoTime() - nanoBeforeIdle;
   } catch (InterruptedException ignore) {
     // stop process when the thread is interrupted
     interrupted = true;
     return false;
   }
   return true;
 }
  /**
   * A test method that allows the caller to artificially stall a requested set of the detector
   * threads for a given amount of time. Used to verify pause detection when consensus occurs, as
   * well as lack of detection when it does not.
   *
   * @param threadNumberMask a mask designating which threads should be stalled.
   * @param stallLength stall length, in nanosecond units
   * @throws InterruptedException if internal sleep implementation throws it
   */
  public void stallDetectorThreads(long threadNumberMask, long stallLength)
      throws InterruptedException {
    long savedMask = stallThreadMask;
    stallThreadMask = threadNumberMask;

    long startTime = TimeServices.nanoTime();
    long endTime = startTime + stallLength;
    for (long remainingTime = stallLength;
        remainingTime > 0;
        remainingTime = endTime - TimeServices.nanoTime()) {
      long timeDelta = Math.min(remainingTime, (pauseNotificationThreshold / 2));
      TimeServices.moveTimeForward(timeDelta);
      TimeUnit.NANOSECONDS.sleep(50000); // give things a chance to propagate.
    }

    stallThreadMask = savedMask;
  }
Ejemplo n.º 4
0
  @Test
  public void testIntervalSampleDeadlock() throws Exception {

    SimplePauseDetector pauseDetector =
        new SimplePauseDetector(
            1000000L /* 1 msec sleep */,
            10000000L /* 10 msec reporting threshold */,
            3 /* thread count */,
            true /* verbose */);

    LatencyStats.setDefaultPauseDetector(pauseDetector);

    final LatencyStats latencyStats = new LatencyStats();

    pauseDetector.skipConsensusTimeTo(TimeServices.nanoTime() + 115 * MSEC);

    TimeServices.moveTimeForward(5000L);
    TimeUnit.NANOSECONDS.sleep(1 * MSEC); // Make sure things have some time to propagate
    TimeServices.moveTimeForward(1000000L);
    TimeUnit.NANOSECONDS.sleep(1 * MSEC); // Make sure things have some time to propagate
    TimeServices.moveTimeForward(2000000L);
    TimeUnit.NANOSECONDS.sleep(1 * MSEC); // Make sure things have some time to propagate
    TimeServices.moveTimeForward(110000000L);
    TimeUnit.NANOSECONDS.sleep(1 * MSEC); // Make sure things have some time to propagate

    try {

      TimeUnit.NANOSECONDS.sleep(10 * MSEC); // Make sure things have some time to propagate

      long startTime = TimeServices.nanoTime();
      try {
        latencyStats.recordLatency(Long.MAX_VALUE);
      } catch (java.lang.IndexOutOfBoundsException e) {
        // Suppress, because this is what we expect
      }

      TimeUnit.NANOSECONDS.sleep(1 * MSEC); // Make sure things have some time to propagate

      ExecutorService executorService = Executors.newFixedThreadPool(1);
      Future<Boolean> future =
          executorService.submit(
              new Runnable() {
                @Override
                public void run() {
                  System.out.println("\nForcing Interval Update; may hang forever:\n");
                  latencyStats.forceIntervalSample();
                  System.out.println("\nCompleted forcing interval sample\n");
                }
              },
              Boolean.TRUE);

      try {
        Boolean response = future.get(5, TimeUnit.SECONDS);
        Assert.assertEquals(Boolean.TRUE, response);
      } catch (TimeoutException e) {
        System.err.println("\nFuture timed out.\n");
        System.out.println("\nMaking sure the thread dies.\n");
        try {
          Field f = LatencyStats.class.getDeclaredField("recordingEndEpoch");
          f.setAccessible(true);
          f.set(latencyStats, (Long) f.get(latencyStats) + 1);
          System.out.println(":" + future.get(5, TimeUnit.SECONDS));
        } catch (Throwable t) {
          t.printStackTrace();
        }
        Assert.fail("Timed out trying to force interval sample.");
      } finally {
        executorService.shutdownNow();
        System.out.println("\nSuccessfully forced interval sample to complete on test failure.\n");
      }

    } catch (InterruptedException ex) {
      // Suppress
    } finally {
      latencyStats.stop();
      pauseDetector.shutdown();
    }
  }
Ejemplo n.º 5
0
  @Test
  public void testLatencyStats() throws Exception {

    SimplePauseDetector pauseDetector =
        new SimplePauseDetector(
            1000000L /* 1 msec sleep */,
            10000000L /* 10 msec reporting threshold */,
            3 /* thread count */,
            true /* verbose */);

    LatencyStats.setDefaultPauseDetector(pauseDetector);

    LatencyStats latencyStats = new LatencyStats();

    pauseDetector.skipConsensusTimeTo(TimeServices.nanoTime() + 115 * MSEC);

    TimeServices.moveTimeForward(5000L);
    TimeUnit.NANOSECONDS.sleep(1 * MSEC); // Make sure things have some time to propagate
    TimeServices.moveTimeForward(1000000L);
    TimeUnit.NANOSECONDS.sleep(1 * MSEC); // Make sure things have some time to propagate
    TimeServices.moveTimeForward(2000000L);
    TimeUnit.NANOSECONDS.sleep(1 * MSEC); // Make sure things have some time to propagate
    TimeServices.moveTimeForward(110000000L);
    TimeUnit.NANOSECONDS.sleep(1 * MSEC); // Make sure things have some time to propagate

    try {

      TimeUnit.NANOSECONDS.sleep(10 * MSEC); // Make sure things have some time to propagate

      long startTime = TimeServices.nanoTime();
      System.out.println(
          "@ "
              + (TimeServices.nanoTime() - startTime)
              + " nsec after start: startTime = "
              + startTime);

      long lastTime = startTime;
      for (int i = 0; i < 2000; i++) {
        pauseDetector.skipConsensusTimeTo(TimeServices.nanoTime() + (4 * MSEC));
        TimeServices.moveTimeForwardMsec(5);
        //                TimeUnit.NANOSECONDS.sleep(100000L); // Give things have some time to
        // propagate
        long now = TimeServices.nanoTime();
        latencyStats.recordLatency(now - lastTime);
        lastTime = now;
      }

      TimeUnit.NANOSECONDS.sleep(1 * MSEC); // Make sure things have some time to propagate

      // @ 10 sec from start
      System.out.println("\nForcing Interval Update:\n");
      latencyStats.forceIntervalSample();

      System.out.println("@ " + (TimeServices.nanoTime() - startTime) + " nsec after start:");
      System.out.println(
          "Estimated interval = "
              + latencyStats.getIntervalEstimator().getEstimatedInterval(lastTime));

      Histogram accumulatedHistogram = latencyStats.getAccumulatedHistogram();
      Histogram intervalHistogram = latencyStats.getIntervalHistogram();

      System.out.println(
          "Accumulated Average latency for 5msec sleeps: "
              + accumulatedHistogram.getMean()
              + ", count = "
              + accumulatedHistogram.getTotalCount());
      System.out.println(
          "Interval Average latency for 5msec sleeps: "
              + intervalHistogram.getMean()
              + ", count = "
              + intervalHistogram.getTotalCount());

      Assert.assertEquals(
          "Accumulated total count should be 2000", 2000, accumulatedHistogram.getTotalCount());

      System.out.println("Pausing detector threads for 5 seconds:");
      pauseDetector.stallDetectorThreads(0x7, 5000 * MSEC);
      TimeUnit.NANOSECONDS.sleep(1 * MSEC); // Make sure things have some time to propagate

      // @ 15 sec from start

      // Report without forcing interval measurement update:

      System.out.println("@ " + (TimeServices.nanoTime() - startTime) + " nsec after start:");
      System.out.println(
          "Estimated interval = "
              + latencyStats.getIntervalEstimator().getEstimatedInterval(TimeServices.nanoTime()));
      accumulatedHistogram = latencyStats.getAccumulatedHistogram();
      intervalHistogram = latencyStats.getIntervalHistogram();

      System.out.println(
          "Post-pause, pre-observation Accumulated Average latency for 5msec sleeps: "
              + accumulatedHistogram.getMean()
              + ", count = "
              + accumulatedHistogram.getTotalCount());
      System.out.println(
          "Post-pause, pre-observation Interval Average latency for 5msec sleeps: "
              + intervalHistogram.getMean()
              + ", count = "
              + intervalHistogram.getTotalCount());

      Assert.assertEquals(
          "Accumulated total count should be 2000", 2000, accumulatedHistogram.getTotalCount());

      // Still @ 15 sec from start
      System.out.println("\nForcing Interval Update:\n");
      latencyStats.forceIntervalSample();

      System.out.println("@ " + (TimeServices.nanoTime() - startTime) + " nsec after start:");
      System.out.println(
          "Estimated interval = "
              + latencyStats.getIntervalEstimator().getEstimatedInterval(TimeServices.nanoTime()));
      accumulatedHistogram = latencyStats.getAccumulatedHistogram();
      intervalHistogram = latencyStats.getIntervalHistogram();

      System.out.println(
          "Post-pause, post-observation Accumulated Average latency for 5msec sleeps: "
              + accumulatedHistogram.getMean()
              + ", count = "
              + accumulatedHistogram.getTotalCount());
      System.out.println(
          "Post-pause, post-observation Interval Average latency for 5msec sleeps: "
              + intervalHistogram.getMean()
              + ", count = "
              + intervalHistogram.getTotalCount());

      Assert.assertEquals(
          "Accumulated total count should be 2000", 2998, accumulatedHistogram.getTotalCount());

      pauseDetector.skipConsensusTimeTo(TimeServices.nanoTime() + (500 * MSEC));
      TimeServices.moveTimeForwardMsec(500);
      TimeUnit.NANOSECONDS.sleep(1 * MSEC); // Make sure things have some time to propagate

      // @ 15.5 sec from start
      System.out.println("\nForcing Interval Update:\n");
      latencyStats.forceIntervalSample();

      System.out.println("@ " + (TimeServices.nanoTime() - startTime) + " nsec after start:");
      System.out.println(
          "Estimated interval = "
              + latencyStats.getIntervalEstimator().getEstimatedInterval(TimeServices.nanoTime()));
      accumulatedHistogram = latencyStats.getAccumulatedHistogram();
      intervalHistogram = latencyStats.getIntervalHistogram();

      System.out.println(
          "Post-pause Accumulated Average latency for 5msec sleeps: "
              + accumulatedHistogram.getMean()
              + ", count = "
              + accumulatedHistogram.getTotalCount());
      System.out.println(
          "Post-pause Interval Average latency for 5msec sleeps: "
              + intervalHistogram.getMean()
              + ", count = "
              + intervalHistogram.getTotalCount());

      Assert.assertEquals(
          "Accumulated total count should be 2000", 2998, accumulatedHistogram.getTotalCount());

      pauseDetector.skipConsensusTimeTo(TimeServices.nanoTime() + (500 * MSEC));
      TimeServices.moveTimeForwardMsec(500);
      TimeUnit.NANOSECONDS.sleep(1 * MSEC); // Make sure things have some time to propagate

      // @ 16 sec from start
      System.out.println("\nForcing Interval Update:\n");
      latencyStats.forceIntervalSample();

      System.out.println("@ " + (TimeServices.nanoTime() - startTime) + " nsec after start:");
      System.out.println(
          "Estimated interval = "
              + latencyStats.getIntervalEstimator().getEstimatedInterval(TimeServices.nanoTime()));
      accumulatedHistogram = latencyStats.getAccumulatedHistogram();
      intervalHistogram = latencyStats.getIntervalHistogram();

      System.out.println(
          "Post-pause Accumulated Average latency for 5msec sleeps: "
              + accumulatedHistogram.getMean()
              + ", count = "
              + accumulatedHistogram.getTotalCount());
      System.out.println(
          "Post-pause Interval Average latency for 5msec sleeps: "
              + intervalHistogram.getMean()
              + ", count = "
              + intervalHistogram.getTotalCount());

      Assert.assertEquals(
          "Accumulated total count should be 2999", 2998, accumulatedHistogram.getTotalCount());

      pauseDetector.skipConsensusTimeTo(TimeServices.nanoTime() + (2000 * MSEC));
      TimeServices.moveTimeForwardMsec(2000);
      TimeUnit.NANOSECONDS.sleep(1 * MSEC); // Make sure things have some time to propagate

      // @ 18 sec from start
      System.out.println("\nForcing Interval Update:\n");
      latencyStats.forceIntervalSample();

      System.out.println("@ " + (TimeServices.nanoTime() - startTime) + " nsec after start:");
      System.out.println(
          "Estimated interval = "
              + latencyStats.getIntervalEstimator().getEstimatedInterval(TimeServices.nanoTime()));
      accumulatedHistogram = latencyStats.getAccumulatedHistogram();
      intervalHistogram = latencyStats.getIntervalHistogram();

      System.out.println(
          "Post-pause Accumulated Average latency for 5msec sleeps: "
              + accumulatedHistogram.getMean()
              + ", count = "
              + accumulatedHistogram.getTotalCount());
      System.out.println(
          "Post-pause Interval Average latency for 5msec sleeps: "
              + intervalHistogram.getMean()
              + ", count = "
              + intervalHistogram.getTotalCount());

      Assert.assertEquals(
          "Accumulated total count should be 2999", 2998, accumulatedHistogram.getTotalCount());

      for (int i = 0; i < 100; i++) {
        pauseDetector.skipConsensusTimeTo(TimeServices.nanoTime() + (5 * MSEC));
        TimeServices.moveTimeForwardMsec(5);
        long now = TimeServices.nanoTime();
        latencyStats.recordLatency(now - lastTime);
        lastTime = now;
      }

      pauseDetector.skipConsensusTimeTo(TimeServices.nanoTime() + (500 * MSEC));
      TimeServices.moveTimeForwardMsec(500);
      TimeUnit.NANOSECONDS.sleep(1 * MSEC); // Make sure things have some time to propagate

      // @ 19 sec from start
      System.out.println("\nForcing Interval Update:\n");
      latencyStats.forceIntervalSample();

      System.out.println("@ " + (TimeServices.nanoTime() - startTime) + " nsec after start:");
      System.out.println(
          "Estimated interval = "
              + latencyStats.getIntervalEstimator().getEstimatedInterval(TimeServices.nanoTime()));
      accumulatedHistogram = latencyStats.getAccumulatedHistogram();
      intervalHistogram = latencyStats.getIntervalHistogram();
      System.out.println(
          "Post-pause Accumulated Average latency for 5msec sleeps: "
              + accumulatedHistogram.getMean()
              + ", count = "
              + accumulatedHistogram.getTotalCount());
      System.out.println(
          "Post-pause Interval Average latency for 5msec sleeps: "
              + intervalHistogram.getMean()
              + ", count = "
              + intervalHistogram.getTotalCount());

      pauseDetector.skipConsensusTimeTo(TimeServices.nanoTime() + (500 * MSEC));
      TimeServices.moveTimeForwardMsec(500);
      TimeUnit.NANOSECONDS.sleep(1 * MSEC); // Make sure things have some time to propagate

      // @ 19.5 sec from start
      System.out.println("\nForcing Interval Update:\n");
      latencyStats.forceIntervalSample();

      System.out.println("@ " + (TimeServices.nanoTime() - startTime) + " nsec after start:");
      System.out.println(
          "Estimated interval = "
              + latencyStats.getIntervalEstimator().getEstimatedInterval(TimeServices.nanoTime()));
      accumulatedHistogram = latencyStats.getAccumulatedHistogram();
      intervalHistogram = latencyStats.getIntervalHistogram();
      System.out.println(
          "Post-pause Accumulated Average latency for 5msec sleeps: "
              + accumulatedHistogram.getMean()
              + ", count = "
              + accumulatedHistogram.getTotalCount());
      System.out.println(
          "Post-pause Interval Average latency for 5msec sleeps: "
              + intervalHistogram.getMean()
              + ", count = "
              + intervalHistogram.getTotalCount());

      Assert.assertEquals(
          "Accumulated total count should be 2000", 3098, accumulatedHistogram.getTotalCount());
    } catch (InterruptedException ex) {

    }

    latencyStats.stop();

    pauseDetector.shutdown();
  }