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 78458d41c10..b5197a0572d 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 @@ -81,7 +81,9 @@ public abstract class ScheduledChore implements Runnable { */ private final Stoppable stopper; - private final MovingAverage timeMeasurement = new WindowMovingAverage(); + private final MovingAverage 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); diff --git a/hbase-common/src/main/java/org/apache/hadoop/hbase/util/ExponentialMovingAverage.java b/hbase-common/src/main/java/org/apache/hadoop/hbase/util/ExponentialMovingAverage.java index ce0c1a38eab..d36ca7a5594 100644 --- a/hbase-common/src/main/java/org/apache/hadoop/hbase/util/ExponentialMovingAverage.java +++ b/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; diff --git a/hbase-common/src/main/java/org/apache/hadoop/hbase/util/MovingAverage.java b/hbase-common/src/main/java/org/apache/hadoop/hbase/util/MovingAverage.java index 768791584cc..55a9766891d 100644 --- a/hbase-common/src/main/java/org/apache/hadoop/hbase/util/MovingAverage.java +++ b/hbase-common/src/main/java/org/apache/hadoop/hbase/util/MovingAverage.java @@ -29,10 +29,16 @@ import org.slf4j.LoggerFactory; *
* In different situation, different {@link MovingAverage} algorithm can be used based on needs. */ -@InterfaceAudience.Public +@InterfaceAudience.Private public abstract class MovingAverage { 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 { */ public T measure(TimeMeasurable 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; } diff --git a/hbase-common/src/main/java/org/apache/hadoop/hbase/util/SimpleMovingAverage.java b/hbase-common/src/main/java/org/apache/hadoop/hbase/util/SimpleMovingAverage.java index 058c9f66a28..4e03a31ff66 100644 --- a/hbase-common/src/main/java/org/apache/hadoop/hbase/util/SimpleMovingAverage.java +++ b/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; } diff --git a/hbase-common/src/main/java/org/apache/hadoop/hbase/util/TimeMeasurable.java b/hbase-common/src/main/java/org/apache/hadoop/hbase/util/TimeMeasurable.java index 111093d716d..5dac95947f9 100644 --- a/hbase-common/src/main/java/org/apache/hadoop/hbase/util/TimeMeasurable.java +++ b/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 { /** diff --git a/hbase-common/src/main/java/org/apache/hadoop/hbase/util/WeightedMovingAverage.java b/hbase-common/src/main/java/org/apache/hadoop/hbase/util/WeightedMovingAverage.java index 33aa56981d3..1f43273bbeb 100644 --- a/hbase-common/src/main/java/org/apache/hadoop/hbase/util/WeightedMovingAverage.java +++ b/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]; diff --git a/hbase-common/src/main/java/org/apache/hadoop/hbase/util/WindowMovingAverage.java b/hbase-common/src/main/java/org/apache/hadoop/hbase/util/WindowMovingAverage.java index fbfc73b6147..1ed950d19ca 100644 --- a/hbase-common/src/main/java/org/apache/hadoop/hbase/util/WindowMovingAverage.java +++ b/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; diff --git a/hbase-common/src/test/java/org/apache/hadoop/hbase/util/TestMovingAverage.java b/hbase-common/src/test/java/org/apache/hadoop/hbase/util/TestMovingAverage.java index 990cacd61c6..8852d5c7e9e 100644 --- a/hbase-common/src/test/java/org/apache/hadoop/hbase/util/TestMovingAverage.java +++ b/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++) {