From 474d200daa795d65ef0992dbb4ad758895d9c4dc Mon Sep 17 00:00:00 2001
From: Andrew Purtell <apurtell@apache.org>
Date: Tue, 9 Jun 2020 09:55:20 -0700
Subject: [PATCH] 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>
---
 .../apache/hadoop/hbase/ScheduledChore.java   | 28 ++++++++-----------
 1 file changed, 12 insertions(+), 16 deletions(-)

diff --git a/hbase-common/src/main/java/org/apache/hadoop/hbase/ScheduledChore.java b/hbase-common/src/main/java/org/apache/hadoop/hbase/ScheduledChore.java
index 86dcb2cbdc1..28af186ff62 100644
--- a/hbase-common/src/main/java/org/apache/hadoop/hbase/ScheduledChore.java
+++ b/hbase-common/src/main/java/org/apache/hadoop/hbase/ScheduledChore.java
@@ -21,8 +21,6 @@ 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;
@@ -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 abstract class ScheduledChore implements Runnable {
     this.period = period;
     this.initialDelay = initialDelay < 0 ? 0 : initialDelay;
     this.timeUnit = unit;
-    this.timeMeasurement = new WindowMovingAverage(name);
   }
 
   /**
@@ -183,18 +176,21 @@ public abstract class ScheduledChore implements Runnable {
       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);