ndimiduk commented on a change in pull request #1749:
URL: https://github.com/apache/hbase/pull/1749#discussion_r429419840
##########
File path:
hbase-common/src/main/java/org/apache/hadoop/hbase/ScheduledChore.java
##########
@@ -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();
Review comment:
A question of clarification. I think what you have is correct, but I'm
asking anyway. We have `EnvironmentEdgeManager`, which abstracts a form of
clock. `System.nanoTime()` is a different form of clock. Is there some case
where we'd want the `nanoTime` to be abstracted behind
`EnvironmentEdgeManager`? My understanding is no, we don't have such a
use-case, because `EnvironmentEdgeManager` is for abstracting over a clock-time
(a la `java.time.Instant`), while `nanoTime` is providing a timer for
calculating a time duration, something that is abstract from a clock-time.
##########
File path:
hbase-common/src/main/java/org/apache/hadoop/hbase/ScheduledChore.java
##########
@@ -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();
- }
+ }
+ if (LOG.isDebugEnabled()) {
+ long end = System.nanoTime();
+ LOG.debug("{} execution time: {} ms.", getName(),
Review comment:
Oh, fun edge case @infraio :) How about a check that `start > 0` and
only log in that case?
##########
File path:
hbase-common/src/main/java/org/apache/hadoop/hbase/ScheduledChore.java
##########
@@ -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)) {
Review comment:
Do we want some duration threshold that triggers escalating the log
level to info (or warn), as was done before?
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
[email protected]
