HBASE-19450 Add log about average execution time for ScheduledChore

Signed-off-by: Sean Busbey <busbey@apache.org>

hbase-common/src/main/java/org/apache/hadoop/hbase/ScheduledChore.java

@@ -21,6 +21,8 @@ package org.apache.hadoop.hbase;
 import java.util.concurrent.ScheduledThreadPoolExecutor;
 import java.util.concurrent.TimeUnit;
 
+import org.apache.hadoop.hbase.util.MovingAverage;
+import org.apache.hadoop.hbase.util.WindowMovingAverage;
 import org.apache.yetus.audience.InterfaceAudience;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
@@ -79,6 +81,8 @@ public abstract class ScheduledChore implements Runnable {
    */
   private final Stoppable stopper;
 
+  private final MovingAverage<Void> timeMeasurement = new WindowMovingAverage();
+
   interface ChoreServicer {
     /**
      * Cancel any ongoing schedules that this chore has with the implementer of this interface.
@@ -183,7 +187,12 @@ public abstract class ScheduledChore implements Runnable {
         if (!initialChoreComplete) {
           initialChoreComplete = initialChore();
         } else {
+          timeMeasurement.measure(() -> {
             chore();
+            return null;
+          });
+          LOG.info(String.format("%s average execution time: %.2f ns.", getName(),
+            timeMeasurement.getAverageTime()));
         }
       } catch (Throwable t) {
         if (LOG.isErrorEnabled()) LOG.error("Caught error", t);

hbase-common/src/main/java/org/apache/hadoop/hbase/util/ExponentialMovingAverage.java

@@ -0,0 +1,79 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one
+ * or more contributor license agreements.  See the NOTICE file
+ * distributed with this work for additional information
+ * regarding copyright ownership.  The ASF licenses this file
+ * to you under the Apache License, Version 2.0 (the
+ * "License"); you may not use this file except in compliance
+ * with the License.  You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package org.apache.hadoop.hbase.util;
+
+import org.apache.yetus.audience.InterfaceAudience;
+
+/**
+ * EMA is similar to {@link WeightedMovingAverage} in weighted, but the weighting factor decrease
+ * exponentially. It brings benefits that it is more sensitive, and can see the trends easily.
+ */
+@InterfaceAudience.Public
+public class ExponentialMovingAverage extends WindowMovingAverage {
+  private double alpha;
+  private double previousAverage;
+  private double currentAverage;
+
+  public ExponentialMovingAverage() {
+    this(DEFAULT_SIZE);
+  }
+
+  public ExponentialMovingAverage(double alpha) {
+    this(DEFAULT_SIZE, alpha);
+  }
+
+  public ExponentialMovingAverage(int size) {
+    this(size, (double) 2 / (1 + size));
+  }
+
+  public ExponentialMovingAverage(int size, double alpha) {
+    super(size);
+    this.previousAverage = -1.0;
+    this.currentAverage = 0.0;
+    this.alpha = alpha;
+  }
+
+  @Override
+  public void updateMostRecentTime(long elapsed) {
+    if (!enoughStatistics()) {
+      previousAverage = super.getAverageTime();
+      super.updateMostRecentTime(elapsed);
+      if (!enoughStatistics()) {
+        return;
+      }
+    }
+    // CurrentEMA = α * currentValue + (1 - α) * previousEMA =>
+    // CurrentEMA = (currentValue - previousEMA) * α + previousEMA
+    // This will reduce multiplication.
+    currentAverage = (elapsed - previousAverage) * alpha + previousAverage;
+    previousAverage = currentAverage;
+  }
+
+  @Override
+  public double getAverageTime() {
+    if (!enoughStatistics()) {
+      return super.getAverageTime();
+    }
+    return currentAverage;
+  }
+
+  double getPrevious() {
+    return previousAverage;
+  }
+}

hbase-common/src/main/java/org/apache/hadoop/hbase/util/MovingAverage.java

@@ -0,0 +1,81 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one
+ * or more contributor license agreements.  See the NOTICE file
+ * distributed with this work for additional information
+ * regarding copyright ownership.  The ASF licenses this file
+ * to you under the Apache License, Version 2.0 (the
+ * "License"); you may not use this file except in compliance
+ * with the License.  You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package org.apache.hadoop.hbase.util;
+
+import org.apache.yetus.audience.InterfaceAudience;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
+/**
+ * The purpose of introduction of {@link MovingAverage} mainly is to measure execution time of a
+ * specific method, which can help us to know its performance fluctuation in response to different
+ * machine states or situations, better case, then to act accordingly.
+ * <br>
+ * In different situation, different {@link MovingAverage} algorithm can be used based on needs.
+ */
+@InterfaceAudience.Public
+public abstract class MovingAverage<T> {
+  private final static Logger LOG = LoggerFactory.getLogger(MovingAverage.class);
+
+  /**
+   * Mark start time of an execution.
+   * @return time in ns.
+   */
+  protected long start() {
+    return System.nanoTime();
+  }
+
+  /**
+   * Mark end time of an execution, and return its interval.
+   * @param startTime start time of an execution
+   * @return elapsed time
+   */
+  protected long stop(long startTime) {
+    return System.nanoTime() - startTime;
+  }
+
+  /**
+   * Measure elapsed time of a measurable method.
+   * @param measurable method implements {@link TimeMeasurable}
+   * @return T it refers to the original return type of the measurable method
+   */
+  public T measure(TimeMeasurable<T> measurable) {
+    long startTime = start();
+    LOG.debug("Start to measure at: {} ns.", startTime);
+    // Here may throw exceptions which should be taken care by caller, not here.
+    // If exception occurs, this time wouldn't count.
+    T result = measurable.measure();
+    long elapsed = stop(startTime);
+    LOG.debug("Elapse: {} ns.", elapsed);
+    updateMostRecentTime(elapsed);
+    return result;
+  }
+
+  /**
+   * Update the most recent data.
+   * @param elapsed elapsed time of the most recent measurement
+   */
+  protected abstract void updateMostRecentTime(long elapsed);
+
+  /**
+   * Get average execution time of the measured method.
+   * @return average time in ns
+   */
+  public abstract double getAverageTime();
+}

hbase-common/src/main/java/org/apache/hadoop/hbase/util/SimpleMovingAverage.java

@@ -0,0 +1,45 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one
+ * or more contributor license agreements.  See the NOTICE file
+ * distributed with this work for additional information
+ * regarding copyright ownership.  The ASF licenses this file
+ * to you under the Apache License, Version 2.0 (the
+ * "License"); you may not use this file except in compliance
+ * with the License.  You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package org.apache.hadoop.hbase.util;
+
+import org.apache.yetus.audience.InterfaceAudience;
+
+/**
+ * SMA measure the overall average execution time of a specific method.
+ */
+@InterfaceAudience.Public
+public class SimpleMovingAverage extends MovingAverage {
+  private double averageTime = 0.0;
+  protected long count = 0;
+
+  public SimpleMovingAverage() {
+    this.averageTime = 0.0;
+    this.count = 0;
+  }
+
+  @Override
+  public void updateMostRecentTime(long elapsed) {
+    averageTime += (elapsed - averageTime) / (++count);
+  }
+
+  @Override
+  public double getAverageTime() {
+    return averageTime;
+  }
+}

hbase-common/src/main/java/org/apache/hadoop/hbase/util/TimeMeasurable.java

@@ -0,0 +1,35 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one
+ * or more contributor license agreements.  See the NOTICE file
+ * distributed with this work for additional information
+ * regarding copyright ownership.  The ASF licenses this file
+ * to you under the Apache License, Version 2.0 (the
+ * "License"); you may not use this file except in compliance
+ * with the License.  You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package org.apache.hadoop.hbase.util;
+
+import org.apache.yetus.audience.InterfaceAudience;
+
+/**
+ * Methods that implement this interface can be measured elapsed time.
+ * It works together with {@link MovingAverage} to take effect.
+ */
+@InterfaceAudience.Public
+public interface TimeMeasurable<T> {
+
+  /**
+   * Measure elapsed time.
+   * @return T
+   */
+  T measure();
+}

hbase-common/src/main/java/org/apache/hadoop/hbase/util/WeightedMovingAverage.java

@@ -0,0 +1,65 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one
+ * or more contributor license agreements.  See the NOTICE file
+ * distributed with this work for additional information
+ * regarding copyright ownership.  The ASF licenses this file
+ * to you under the Apache License, Version 2.0 (the
+ * "License"); you may not use this file except in compliance
+ * with the License.  You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package org.apache.hadoop.hbase.util;
+
+import org.apache.yetus.audience.InterfaceAudience;
+
+/**
+ * Different from SMA {@link SimpleMovingAverage}, WeightedMovingAverage gives each data different
+ * weight. And it is based on {@link WindowMovingAverage}, such that it only focus on the last N.
+ */
+@InterfaceAudience.Public
+public class WeightedMovingAverage extends WindowMovingAverage {
+  private int[] coefficient;
+  private int denominator;
+
+  public WeightedMovingAverage() {
+    this(DEFAULT_SIZE);
+  }
+
+  public WeightedMovingAverage(int size) {
+    super(size);
+    int length = getNumberOfStatistics();
+    denominator = length * (length + 1) / 2;
+    coefficient = new int[length];
+    // E.g. default size is 5, coefficient should be [1, 2, 3, 4, 5]
+    for (int i = 0; i < length; i++) {
+      coefficient[i] = i + 1;
+    }
+  }
+
+  @Override
+  public double getAverageTime() {
+    if (!enoughStatistics()) {
+      return super.getAverageTime();
+    }
+    // only we get enough statistics, then start WMA.
+    double average = 0.0;
+    int coIndex = 0;
+    int length = getNumberOfStatistics();
+    // tmIndex, it points to the oldest data.
+    for (int tmIndex = (getMostRecentPosistion() + 1) % length;
+         coIndex < length;
+         coIndex++, tmIndex = (++tmIndex) % length) {
+      // start the multiplication from oldest to newest
+      average += coefficient[coIndex] * getStatisticsAtIndex(tmIndex);
+    }
+    return average / denominator;
+  }
+}

hbase-common/src/main/java/org/apache/hadoop/hbase/util/WindowMovingAverage.java

@@ -0,0 +1,118 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one
+ * or more contributor license agreements.  See the NOTICE file
+ * distributed with this work for additional information
+ * regarding copyright ownership.  The ASF licenses this file
+ * to you under the Apache License, Version 2.0 (the
+ * "License"); you may not use this file except in compliance
+ * with the License.  You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package org.apache.hadoop.hbase.util;
+
+import org.apache.yetus.audience.InterfaceAudience;
+
+/**
+ * Instead of calculate a whole time average, this class focus on the last N.
+ * The last N is stored in a circle array.
+ */
+@InterfaceAudience.Public
+public class WindowMovingAverage extends MovingAverage {
+  protected final static int DEFAULT_SIZE = 5;
+
+  // The last n statistics.
+  protected long[] lastN;
+  // The index of the most recent statistics.
+  protected int mostRecent;
+  // If it travels a round.
+  protected boolean oneRound;
+
+  public WindowMovingAverage() {
+    this(DEFAULT_SIZE);
+  }
+
+  public WindowMovingAverage(int size) {
+    this.lastN = new long[size <= 0 ? DEFAULT_SIZE : size];
+    this.mostRecent = -1;
+    this.oneRound = false;
+  }
+
+  @Override
+  protected void updateMostRecentTime(long elapsed) {
+    int index = moveForwardMostRecentPosistion();
+    lastN[index] = elapsed;
+  }
+
+  @Override
+  public double getAverageTime() {
+    return enoughStatistics() ?
+      (double) sum(getNumberOfStatistics()) / getNumberOfStatistics() :
+      (double) sum(getMostRecentPosistion() + 1) / (getMostRecentPosistion() + 1);
+  }
+
+  /**
+   * Check if there are enough statistics.
+   * @return true if lastN is full
+   */
+  protected boolean enoughStatistics() {
+    return oneRound;
+  }
+
+  /**
+   * @return number of statistics
+   */
+  protected int getNumberOfStatistics() {
+    return lastN.length;
+  }
+
+  /**
+   * Get statistics at index.
+   * @param index index of bar
+   * @return statistics
+   */
+  protected long getStatisticsAtIndex(int index) {
+    if (index < 0 || index >= getNumberOfStatistics()) {
+      // This case should not happen, but a prudent check.
+      throw new IndexOutOfBoundsException();
+    }
+    return lastN[index];
+  }
+
+  /**
+   * @return index of most recent
+   */
+  protected int getMostRecentPosistion() {
+    return mostRecent;
+  }
+
+  /**
+   * Move forward the most recent index.
+   * @return the most recent index
+   */
+  protected int moveForwardMostRecentPosistion() {
+    int index = ++mostRecent;
+    if (!oneRound && index == getNumberOfStatistics()) {
+      // Back to the head of the lastN, from now on will
+      // start to evict oldest value.
+      oneRound = true;
+    }
+    mostRecent = index % getNumberOfStatistics();
+    return mostRecent;
+  }
+
+  private long sum(int bound) {
+    long sum = 0;
+    for (int i = 0; i < bound; i++) {
+      sum += getStatisticsAtIndex(i);
+    }
+    return sum;
+  }
+}

hbase-common/src/test/java/org/apache/hadoop/hbase/util/TestMovingAverage.java

@@ -0,0 +1,152 @@
+/**
+ * Licensed to the Apache Software Foundation (ASF) under one
+ * or more contributor license agreements.  See the NOTICE file
+ * distributed with this work for additional information
+ * regarding copyright ownership.  The ASF licenses this file
+ * to you under the Apache License, Version 2.0 (the
+ * "License"); you may not use this file except in compliance
+ * with the License.  You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package org.apache.hadoop.hbase.util;
+
+import org.apache.hadoop.hbase.HBaseClassTestRule;
+import org.apache.hadoop.hbase.testclassification.SmallTests;
+import org.junit.Assert;
+import org.junit.ClassRule;
+import org.junit.Test;
+import org.junit.experimental.categories.Category;
+
+@Category(SmallTests.class)
+public class TestMovingAverage {
+
+  @ClassRule
+  public static final HBaseClassTestRule CLASS_RULE =
+      HBaseClassTestRule.forClass(TestMovingAverage.class);
+
+  private long[] data = {1, 12, 13, 24, 25, 26, 37, 38, 39, 40};
+  private double delta = 0.1;
+
+  @Test
+  public void testSimpleMovingAverage() throws Exception {
+    MovingAverage<?> algorithm = new SimpleMovingAverage();
+    int index = 0;
+    // [1, 12, 13, 24]
+    int bound = 4;
+    for (; index < bound; index++) {
+      algorithm.updateMostRecentTime(data[index]);
+    }
+    Assert.assertEquals(12.5, algorithm.getAverageTime(), delta);
+    // [1, 12, 13, 24, 25]
+    bound = 5;
+    for (; index < bound; index++) {
+      algorithm.updateMostRecentTime(data[index]);
+    }
+    Assert.assertEquals(15.0, algorithm.getAverageTime(), delta);
+    // [1, 12, 13, 24, 25, 26, 37, 38]
+    bound = 8;
+    for (; index < bound; index++) {
+      algorithm.updateMostRecentTime(data[index]);
+    }
+    Assert.assertEquals(22.0, algorithm.getAverageTime(), delta);
+    // [1, 12, 13, 24, 25, 26, 37, 38, 39, 40]
+    for (; index < data.length; index++) {
+      algorithm.updateMostRecentTime(data[index]);
+    }
+    Assert.assertEquals(25.5, algorithm.getAverageTime(), delta);
+  }
+
+  @Test
+  public void testWindowMovingAverage() throws Exception {
+    // Default size is 5.
+    MovingAverage<?> algorithm = new WindowMovingAverage();
+    int index = 0;
+    // [1, 12, 13, 24]
+    int bound = 4;
+    for (; index < bound; index++) {
+      algorithm.updateMostRecentTime(data[index]);
+    }
+    Assert.assertEquals(12.5, algorithm.getAverageTime(), delta);
+    // [1, 12, 13, 24, 25]
+    bound = 5;
+    for (; index < bound; index++) {
+      algorithm.updateMostRecentTime(data[index]);
+    }
+    Assert.assertEquals(15.0, algorithm.getAverageTime(), delta);
+    // [24, 25, 26, 37, 38]
+    bound = 8;
+    for (; index < bound; index++) {
+      algorithm.updateMostRecentTime(data[index]);
+    }
+    Assert.assertEquals(30.0, algorithm.getAverageTime(), delta);
+    // [26, 37, 38, 39, 40]
+    for (; index < data.length; index++) {
+      algorithm.updateMostRecentTime(data[index]);
+    }
+    Assert.assertEquals(36.0, algorithm.getAverageTime(), delta);
+  }
+
+  @Test
+  public void testWeightedMovingAverage() throws Exception {
+    // Default size is 5.
+    MovingAverage<?> algorithm = new WeightedMovingAverage();
+    int index = 0;
+    // [1, 12, 13, 24]
+    int bound = 4;
+    for (; index < bound; index++) {
+      algorithm.updateMostRecentTime(data[index]);
+    }
+    Assert.assertEquals(12.5, algorithm.getAverageTime(), delta);
+    // [1, 12, 13, 24, 25]
+    bound = 5;
+    for (; index < bound; index++) {
+      algorithm.updateMostRecentTime(data[index]);
+    }
+    Assert.assertEquals(15.0, algorithm.getAverageTime(), delta);
+    // [24, 25, 26, 37, 38]
+    bound = 8;
+    for (; index < bound; index++) {
+      algorithm.updateMostRecentTime(data[index]);
+    }
+    Assert.assertEquals(32.67, algorithm.getAverageTime(), delta);
+    // [26, 37, 38, 39, 40]
+    for (; index < data.length; index++) {
+      algorithm.updateMostRecentTime(data[index]);
+    }
+    Assert.assertEquals(38.0, algorithm.getAverageTime(), delta);
+  }
+
+  @Test
+  public void testExponentialMovingAverage() throws Exception {
+    // [1, 12, 13, 24, 25, 26, 37, 38, 39, 40]
+    MovingAverage<?> algorithm = new ExponentialMovingAverage();
+    int index = 0;
+    int bound = 5;
+    for (; index < bound; index++) {
+      algorithm.updateMostRecentTime(data[index]);
+    }
+    Assert.assertEquals(15.0, algorithm.getAverageTime(), delta);
+    bound = 6;
+    for (; index < bound; index++) {
+      algorithm.updateMostRecentTime(data[index]);
+    }
+    Assert.assertEquals(18.67, algorithm.getAverageTime(), delta);
+    bound = 8;
+    for (; index < bound; index++) {
+      algorithm.updateMostRecentTime(data[index]);
+    }
+    Assert.assertEquals(29.16, algorithm.getAverageTime(), delta);
+    for (; index < data.length; index++) {
+      algorithm.updateMostRecentTime(data[index]);
+    }
+    Assert.assertEquals(34.97, algorithm.getAverageTime(), delta);
+  }
+}