[GitHub] [hbase] ndimiduk commented on a change in pull request #1749: HBASE-24367 ScheduledChore log elapsed timespan in a human-friendly format

[GitBox <gi...@apache.org>]

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:
users@infra.apache.org