Apache
/
hbase
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

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>
This commit is contained in:
Andrew Purtell 2020-06-09 09:55:20 -07:00 committed by GitHub
parent 15ddded26b
commit 474d200daa
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
1 changed files with 12 additions and 16 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

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

@ -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);