From b19d87c2b76e2fa0fc10474fefc616bd9626024d Mon Sep 17 00:00:00 2001
From: Rajesh Balamohan <rbalamohan@cloudera.com>
Date: Thu, 2 Jan 2020 17:01:41 +0000
Subject: [PATCH] HADOOP-16751. DurationInfo text parsing/formatting should be
 moved out of hotpath.

Contributed by Rajesh Balamohan

Change-Id: Icc3dcfa81aa69164f2c088f9b533d231138cbb8b
---
 .../org/apache/hadoop/util/DurationInfo.java  | 25 ++++++++++++++-----
 .../apache/hadoop/util/TestDurationInfo.java  |  8 ++++++
 2 files changed, 27 insertions(+), 6 deletions(-)

diff --git a/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/util/DurationInfo.java b/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/util/DurationInfo.java
index 605d060270f..e0e690ac2f8 100644
--- a/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/util/DurationInfo.java
+++ b/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/util/DurationInfo.java
@@ -23,6 +23,8 @@ import org.slf4j.Logger;
 import org.apache.hadoop.classification.InterfaceAudience.Public;
 import org.apache.hadoop.classification.InterfaceStability.Unstable;
 
+import java.util.function.Supplier;
+
 /**
  * A duration with logging of final state at info or debug
  * in the {@code close()} call.
@@ -33,7 +35,10 @@ import org.apache.hadoop.classification.InterfaceStability.Unstable;
 @Unstable
 public class DurationInfo extends OperationDuration
     implements AutoCloseable {
-  private final String text;
+
+  private final Supplier<String> text;
+
+  private String textStr;
 
   private final Logger log;
 
@@ -65,19 +70,25 @@ public class DurationInfo extends OperationDuration
       boolean logAtInfo,
       String format,
       Object... args) {
-    this.text = String.format(format, args);
+    this.text = () -> String.format(format, args);
     this.log = log;
     this.logAtInfo = logAtInfo;
     if (logAtInfo) {
-      log.info("Starting: {}", text);
+      log.info("Starting: {}", getFormattedText());
     } else {
-      log.debug("Starting: {}", text);
+      if (log.isDebugEnabled()) {
+        log.debug("Starting: {}", getFormattedText());
+      }
     }
   }
 
+  private String getFormattedText() {
+    return (textStr == null) ? (textStr = text.get()) : textStr;
+  }
+
   @Override
   public String toString() {
-    return text + ": duration " + super.toString();
+    return getFormattedText() + ": duration " + super.toString();
   }
 
   @Override
@@ -86,7 +97,9 @@ public class DurationInfo extends OperationDuration
     if (logAtInfo) {
       log.info("{}", this);
     } else {
-      log.debug("{}", this);
+      if (log.isDebugEnabled()) {
+        log.debug("{}", this);
+      }
     }
   }
 }
diff --git a/hadoop-common-project/hadoop-common/src/test/java/org/apache/hadoop/util/TestDurationInfo.java b/hadoop-common-project/hadoop-common/src/test/java/org/apache/hadoop/util/TestDurationInfo.java
index d1fa70319eb..b6abde87629 100644
--- a/hadoop-common-project/hadoop-common/src/test/java/org/apache/hadoop/util/TestDurationInfo.java
+++ b/hadoop-common-project/hadoop-common/src/test/java/org/apache/hadoop/util/TestDurationInfo.java
@@ -35,6 +35,14 @@ public class TestDurationInfo {
     Thread.sleep(1000);
     info.finished();
     Assert.assertTrue(info.value() > 0);
+
+    info = new DurationInfo(log, true, "test format %s", "value");
+    Assert.assertEquals("test format value: duration 0:00.000s",
+        info.toString());
+
+    info = new DurationInfo(log, false, "test format %s", "value");
+    Assert.assertEquals("test format value: duration 0:00.000s",
+        info.toString());
   }
 
   @Test