HBASE-19450 Addendum Limit logging of chore execution time at INFO to once per 5 minutes.

* Ensure MovingAverage related classes are IA.Private
* Move trace logging into MovingAverage class

Signed-off-by: Duo Zhang <zhangduo@apache.org>

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

@@ -81,7 +81,9 @@ public abstract class ScheduledChore implements Runnable {
    */
   private final Stoppable stopper;
 
-  private final MovingAverage<Void> timeMeasurement = new WindowMovingAverage();
+  private final MovingAverage<Void> timeMeasurement;
+  private static final long FIVE_MINUTES_IN_NANOS = TimeUnit.MINUTES.toNanos(5L);
+  private long lastLog = System.nanoTime();
 
   interface ChoreServicer {
     /**
@@ -122,11 +124,7 @@ public abstract class ScheduledChore implements Runnable {
   @InterfaceAudience.Private
   @VisibleForTesting
   protected ScheduledChore() {
-    this.name = null;
-    this.stopper = null;
-    this.period = 0;
-    this.initialDelay = DEFAULT_INITIAL_DELAY;
-    this.timeUnit = DEFAULT_TIME_UNIT;
+    this("TestChore", null, 0, DEFAULT_INITIAL_DELAY, DEFAULT_TIME_UNIT);
   }
 
   /**
@@ -167,6 +165,7 @@ public abstract class ScheduledChore implements Runnable {
     this.period = period;
     this.initialDelay = initialDelay < 0 ? 0 : initialDelay;
     this.timeUnit = unit;
+    this.timeMeasurement = new WindowMovingAverage(name);
   }
 
   /**
@@ -191,8 +190,11 @@ public abstract class ScheduledChore implements Runnable {
             chore();
             return null;
           });
-          LOG.info(String.format("%s average execution time: %.2f ns.", getName(),
-            timeMeasurement.getAverageTime()));
+          if (LOG.isInfoEnabled() && (System.nanoTime() - lastLog > FIVE_MINUTES_IN_NANOS)) {
+            LOG.info("{} average execution time: {} ns.", getName(),
+                (long)(timeMeasurement.getAverageTime()));
+            lastLog = System.nanoTime();
+          }
         }
       } catch (Throwable t) {
         if (LOG.isErrorEnabled()) LOG.error("Caught error", t);

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

@@ -24,26 +24,26 @@ 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
+@InterfaceAudience.Private
 public class ExponentialMovingAverage extends WindowMovingAverage {
   private double alpha;
   private double previousAverage;
   private double currentAverage;
 
-  public ExponentialMovingAverage() {
-    this(DEFAULT_SIZE);
+  public ExponentialMovingAverage(String label) {
+    this(label, DEFAULT_SIZE);
   }
 
-  public ExponentialMovingAverage(double alpha) {
-    this(DEFAULT_SIZE, alpha);
+  public ExponentialMovingAverage(String label, double alpha) {
+    this(label, DEFAULT_SIZE, alpha);
   }
 
-  public ExponentialMovingAverage(int size) {
-    this(size, (double) 2 / (1 + size));
+  public ExponentialMovingAverage(String label, int size) {
+    this(label, size, (double) 2 / (1 + size));
   }
 
-  public ExponentialMovingAverage(int size, double alpha) {
-    super(size);
+  public ExponentialMovingAverage(String label, int size, double alpha) {
+    super(label, size);
     this.previousAverage = -1.0;
     this.currentAverage = 0.0;
     this.alpha = alpha;

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

@@ -29,10 +29,16 @@ import org.slf4j.LoggerFactory;
  * <br>
  * In different situation, different {@link MovingAverage} algorithm can be used based on needs.
  */
-@InterfaceAudience.Public
+@InterfaceAudience.Private
 public abstract class MovingAverage<T> {
   private final static Logger LOG = LoggerFactory.getLogger(MovingAverage.class);
 
+  protected final String label;
+
+  protected MovingAverage(String label) {
+    this.label = label;
+  }
+
   /**
    * Mark start time of an execution.
    * @return time in ns.
@@ -57,12 +63,12 @@ public abstract class MovingAverage<T> {
    */
   public T measure(TimeMeasurable<T> measurable) {
     long startTime = start();
-    LOG.debug("Start to measure at: {} ns.", startTime);
+    LOG.trace("{} - start to measure at: {} ns.", label, 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);
+    LOG.trace("{} - elapse: {} ns.", label, elapsed);
     updateMostRecentTime(elapsed);
     return result;
   }

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

@@ -23,12 +23,13 @@ import org.apache.yetus.audience.InterfaceAudience;
 /**
  * SMA measure the overall average execution time of a specific method.
  */
-@InterfaceAudience.Public
+@InterfaceAudience.Private
 public class SimpleMovingAverage extends MovingAverage {
   private double averageTime = 0.0;
   protected long count = 0;
 
-  public SimpleMovingAverage() {
+  public SimpleMovingAverage(String label) {
+    super(label);
     this.averageTime = 0.0;
     this.count = 0;
   }

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

@@ -24,7 +24,7 @@ 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
+@InterfaceAudience.Private
 public interface TimeMeasurable<T> {
 
   /**

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

@@ -24,17 +24,17 @@ 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
+@InterfaceAudience.Private
 public class WeightedMovingAverage extends WindowMovingAverage {
   private int[] coefficient;
   private int denominator;
 
-  public WeightedMovingAverage() {
-    this(DEFAULT_SIZE);
+  public WeightedMovingAverage(String label) {
+    this(label, DEFAULT_SIZE);
   }
 
-  public WeightedMovingAverage(int size) {
-    super(size);
+  public WeightedMovingAverage(String label, int size) {
+    super(label, size);
     int length = getNumberOfStatistics();
     denominator = length * (length + 1) / 2;
     coefficient = new int[length];

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

@@ -24,7 +24,7 @@ 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
+@InterfaceAudience.Private
 public class WindowMovingAverage extends MovingAverage {
   protected final static int DEFAULT_SIZE = 5;
 
@@ -35,11 +35,12 @@ public class WindowMovingAverage extends MovingAverage {
   // If it travels a round.
   protected boolean oneRound;
 
-  public WindowMovingAverage() {
-    this(DEFAULT_SIZE);
+  public WindowMovingAverage(String label) {
+    this(label, DEFAULT_SIZE);
   }
 
-  public WindowMovingAverage(int size) {
+  public WindowMovingAverage(String label, int size) {
+    super(label);
     this.lastN = new long[size <= 0 ? DEFAULT_SIZE : size];
     this.mostRecent = -1;
     this.oneRound = false;

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

@@ -22,8 +22,10 @@ import org.apache.hadoop.hbase.HBaseClassTestRule;
 import org.apache.hadoop.hbase.testclassification.SmallTests;
 import org.junit.Assert;
 import org.junit.ClassRule;
+import org.junit.Rule;
 import org.junit.Test;
 import org.junit.experimental.categories.Category;
+import org.junit.rules.TestName;
 
 @Category(SmallTests.class)
 public class TestMovingAverage {
@@ -32,12 +34,15 @@ public class TestMovingAverage {
   public static final HBaseClassTestRule CLASS_RULE =
       HBaseClassTestRule.forClass(TestMovingAverage.class);
 
+  @Rule
+  public TestName name = new TestName();
+
   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();
+    MovingAverage<?> algorithm = new SimpleMovingAverage(name.getMethodName());
     int index = 0;
     // [1, 12, 13, 24]
     int bound = 4;
@@ -67,7 +72,7 @@ public class TestMovingAverage {
   @Test
   public void testWindowMovingAverage() throws Exception {
     // Default size is 5.
-    MovingAverage<?> algorithm = new WindowMovingAverage();
+    MovingAverage<?> algorithm = new WindowMovingAverage(name.getMethodName());
     int index = 0;
     // [1, 12, 13, 24]
     int bound = 4;
@@ -97,7 +102,7 @@ public class TestMovingAverage {
   @Test
   public void testWeightedMovingAverage() throws Exception {
     // Default size is 5.
-    MovingAverage<?> algorithm = new WeightedMovingAverage();
+    MovingAverage<?> algorithm = new WeightedMovingAverage(name.getMethodName());
     int index = 0;
     // [1, 12, 13, 24]
     int bound = 4;
@@ -127,7 +132,7 @@ public class TestMovingAverage {
   @Test
   public void testExponentialMovingAverage() throws Exception {
     // [1, 12, 13, 24, 25, 26, 37, 38, 39, 40]
-    MovingAverage<?> algorithm = new ExponentialMovingAverage();
+    MovingAverage<?> algorithm = new ExponentialMovingAverage(name.getMethodName());
     int index = 0;
     int bound = 5;
     for (; index < bound; index++) {