HBASE-24367 ScheduledChore log elapsed timespan in a human-friendly format (#1749)

Signed-off-by: Nick Dimiduk <ndimiduk@apache.org>
Signed-off-by: Guanghao Zhang <zghao@apache.org>
Signed-off-by: Viraj Jasani <vjasani@apache.org>

Author: apurtell

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

@@ -21,8 +21,6 @@
 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;
@@ -81,10 +79,6 @@ public abstract class ScheduledChore implements Runnable {
    */
   private final Stoppable stopper;
 
-  private final MovingAverage<Void> timeMeasurement;
-  private static final long FIVE_MINUTES_IN_NANOS = TimeUnit.MINUTES.toNanos(5L);
-  private long lastLog = System.nanoTime();
-
   interface ChoreServicer {
     /**
      * Cancel any ongoing schedules that this chore has with the implementer of this interface.
@@ -165,7 +159,6 @@ public ScheduledChore(final String name, Stoppable stopper, final int period,
     this.period = period;
     this.initialDelay = initialDelay < 0 ? 0 : initialDelay;
     this.timeUnit = unit;
-    this.timeMeasurement = new WindowMovingAverage(name);
   }
 
   /**
@@ -183,18 +176,21 @@ public void run() {
       if (LOG.isInfoEnabled()) LOG.info("Chore: " + getName() + " was stopped");
     } else {
       try {
+        // TODO: Histogram metrics per chore name.
+        // For now, just measure and log if DEBUG level logging is enabled.
+        long start = 0;
+        if (LOG.isDebugEnabled()) {
+          start = System.nanoTime();
+        }
         if (!initialChoreComplete) {
           initialChoreComplete = initialChore();
         } else {
-          timeMeasurement.measure(() -> {
-            chore();
-            return null;
-          });
-          if (LOG.isInfoEnabled() && (System.nanoTime() - lastLog > FIVE_MINUTES_IN_NANOS)) {
-            LOG.info("{} average execution time: {} ns.", getName(),
-                (long)(timeMeasurement.getAverageTime()));
-            lastLog = System.nanoTime();
-          }
+          chore();
+        }
+        if (LOG.isDebugEnabled() && start > 0) {
+          long end = System.nanoTime();
+          LOG.debug("{} execution time: {} ms.", getName(),
+            TimeUnit.NANOSECONDS.toMillis(end - start));
         }
       } catch (Throwable t) {
         if (LOG.isErrorEnabled()) LOG.error("Caught error", t);