From 67f9afc722b21d67e81e5d70359b7d55c43689de Mon Sep 17 00:00:00 2001 From: Reid Chan Date: Thu, 14 Dec 2017 19:53:25 +0800 Subject: [PATCH] HBASE-19450 Add log about average execution time for ScheduledChore Signed-off-by: Sean Busbey --- .../apache/hadoop/hbase/ScheduledChore.java | 11 +- .../hbase/util/ExponentialMovingAverage.java | 79 +++++++++ .../hadoop/hbase/util/MovingAverage.java | 81 ++++++++++ .../hbase/util/SimpleMovingAverage.java | 45 ++++++ .../hadoop/hbase/util/TimeMeasurable.java | 35 ++++ .../hbase/util/WeightedMovingAverage.java | 65 ++++++++ .../hbase/util/WindowMovingAverage.java | 118 ++++++++++++++ .../hadoop/hbase/util/TestMovingAverage.java | 152 ++++++++++++++++++ 8 files changed, 585 insertions(+), 1 deletion(-) create mode 100644 hbase-common/src/main/java/org/apache/hadoop/hbase/util/ExponentialMovingAverage.java create mode 100644 hbase-common/src/main/java/org/apache/hadoop/hbase/util/MovingAverage.java create mode 100644 hbase-common/src/main/java/org/apache/hadoop/hbase/util/SimpleMovingAverage.java create mode 100644 hbase-common/src/main/java/org/apache/hadoop/hbase/util/TimeMeasurable.java create mode 100644 hbase-common/src/main/java/org/apache/hadoop/hbase/util/WeightedMovingAverage.java create mode 100644 hbase-common/src/main/java/org/apache/hadoop/hbase/util/WindowMovingAverage.java create mode 100644 hbase-common/src/test/java/org/apache/hadoop/hbase/util/TestMovingAverage.java 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 468b5d30c35..78458d41c10 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,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 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 { - chore(); + 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); 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 new file mode 100644 index 00000000000..ce0c1a38eab --- /dev/null +++ b/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; + } +} 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 new file mode 100644 index 00000000000..768791584cc --- /dev/null +++ b/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. + *
+ * In different situation, different {@link MovingAverage} algorithm can be used based on needs. + */ +@InterfaceAudience.Public +public abstract class MovingAverage { + 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 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(); +} 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 new file mode 100644 index 00000000000..058c9f66a28 --- /dev/null +++ b/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; + } +} 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 new file mode 100644 index 00000000000..111093d716d --- /dev/null +++ b/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 { + + /** + * Measure elapsed time. + * @return T + */ + T measure(); +} 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 new file mode 100644 index 00000000000..33aa56981d3 --- /dev/null +++ b/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; + } +} 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 new file mode 100644 index 00000000000..fbfc73b6147 --- /dev/null +++ b/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; + } +} 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 new file mode 100644 index 00000000000..990cacd61c6 --- /dev/null +++ b/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); + } +}