Allow AutoProfiler to not log if below a caller-specified threshold, and set the threshold to 100 ms for two common local actions to avoid spamming the INFO log too much. I would be happy to set the threshold even higher.

--
MOS_MIGRATED_REVID=113413914

1 files changed, 62 insertions, 17 deletions

diff --git a/src/main/java/com/google/devtools/build/lib/profiler/AutoProfiler.java b/src/main/java/com/google/devtools/build/lib/profiler/AutoProfiler.java
index 33977ea58e..bec813a5ce 100644
--- a/src/main/java/com/google/devtools/build/lib/profiler/AutoProfiler.java
+++ b/src/main/java/com/google/devtools/build/lib/profiler/AutoProfiler.java
@@ -22,6 +22,8 @@ import java.util.concurrent.atomic.AtomicBoolean;
 import java.util.concurrent.atomic.AtomicReference;
 import java.util.logging.Logger;
 
+import javax.annotation.Nullable;
+
 /**
  * A convenient way to actively get access to timing information (e.g. for logging and/or
  * profiling purposes) with minimal boilerplate. The lack of boilerplate comes at a performance
@@ -104,7 +106,8 @@ public class AutoProfiler implements AutoCloseable {
    * {@link #logged} et al.
    */
   public interface LoggingElapsedTimeReceiverFactory {
-    ElapsedTimeReceiver create(String taskDescription, Logger logger, TimeUnit timeUnit);
+    ElapsedTimeReceiver create(
+        String taskDescription, Logger logger, long minTimeForLogging, TimeUnit timeUnit);
   }
 
   /**
@@ -128,14 +131,31 @@ public class AutoProfiler implements AutoCloseable {
   }
 
   /**
-   * Returns an {@link AutoProfiler} that, when closed, logs the elapsed time the given
+   * Returns an {@link AutoProfiler} that, when closed, logs the elapsed time in the given
    * {@link TimeUnit} to the given {@link Logger}.
    *
    * <p>The returned {@link AutoProfiler} is thread-safe.
    */
   public static AutoProfiler logged(String taskDescription, Logger logger, TimeUnit timeUnit) {
-    return create(LOGGING_ELAPSED_TIME_RECEIVER_FACTORY_REF.get().create(
-        taskDescription, logger, timeUnit));
+    return create(
+        LOGGING_ELAPSED_TIME_RECEIVER_FACTORY_REF
+            .get()
+            .create(taskDescription, logger, 0L, timeUnit));
+  }
+
+  /**
+   * Returns an {@link AutoProfiler} that, when closed, logs the elapsed time in milliseconds to the
+   * given {@link Logger} if it is greater than {@code minTimeForLoggingInMilliseconds}.
+   *
+   * <p>The returned {@link AutoProfiler} is thread-safe.
+   */
+  public static AutoProfiler logged(
+      String taskDescription, Logger logger, long minTimeForLoggingInMilliseconds) {
+    return create(
+        LOGGING_ELAPSED_TIME_RECEIVER_FACTORY_REF
+            .get()
+            .create(
+                taskDescription, logger, minTimeForLoggingInMilliseconds, TimeUnit.MILLISECONDS));
   }
 
   /**
@@ -158,8 +178,10 @@ public class AutoProfiler implements AutoCloseable {
       ProfilerTask profilerTaskType, Logger logger) {
     ElapsedTimeReceiver profilingReceiver =
         new ProfilingElapsedTimeReceiver(taskDescription, profilerTaskType);
-    ElapsedTimeReceiver loggingReceiver = LOGGING_ELAPSED_TIME_RECEIVER_FACTORY_REF.get().create(
-        taskDescription, logger, TimeUnit.MILLISECONDS);
+    ElapsedTimeReceiver loggingReceiver =
+        LOGGING_ELAPSED_TIME_RECEIVER_FACTORY_REF
+            .get()
+            .create(taskDescription, logger, 0L, TimeUnit.MILLISECONDS);
     return create(new SequencedElapsedTimeReceiver(profilingReceiver, loggingReceiver));
   }
 
@@ -241,33 +263,56 @@ public class AutoProfiler implements AutoCloseable {
     }
   }
 
-  private static class LoggingElapsedTimeReceiver implements ElapsedTimeReceiver {
+  /**
+   * {@link ElapsedTimeReceiver} that logs a message in {@link #accept} if the elapsed time is at
+   * least a given threshold.
+   */
+  public static class LoggingElapsedTimeReceiver implements ElapsedTimeReceiver {
     private static final LoggingElapsedTimeReceiverFactory FACTORY =
         new LoggingElapsedTimeReceiverFactory() {
           @Override
-          public ElapsedTimeReceiver create(String taskDescription, Logger logger,
-              TimeUnit timeUnit) {
-            return new LoggingElapsedTimeReceiver(taskDescription, logger, timeUnit);
+          public ElapsedTimeReceiver create(
+              String taskDescription, Logger logger, long minTimeForLogging, TimeUnit timeUnit) {
+            return new LoggingElapsedTimeReceiver(
+                taskDescription, logger, minTimeForLogging, timeUnit);
           }
         };
 
     private final String taskDescription;
-    private final Logger logger;
+    protected final Logger logger;
     private final TimeUnit timeUnit;
+    private final long minNanosForLogging;
 
-    private LoggingElapsedTimeReceiver(String taskDescription, Logger logger, TimeUnit timeUnit) {
+    protected LoggingElapsedTimeReceiver(
+        String taskDescription, Logger logger, long minTimeForLogging, TimeUnit timeUnit) {
       this.taskDescription = taskDescription;
       this.logger = logger;
       this.timeUnit = timeUnit;
+      this.minNanosForLogging = timeUnit.toNanos(minTimeForLogging);
     }
 
-    @Override
-    public void accept(long elapsedTimeNanos) {
-      if (elapsedTimeNanos > 0) {
-        logger.info(String.format("Spent %d %s doing %s",
+    /**
+     * Returns a message about the amount of time spent doing a task if {@code elapsedTimeNanos} is
+     * at least {@link #minNanosForLogging} and null otherwise.
+     */
+    @Nullable
+    protected String loggingMessage(long elapsedTimeNanos) {
+      if (elapsedTimeNanos >= minNanosForLogging) {
+        return String.format(
+            "Spent %d %s doing %s",
             timeUnit.convert(elapsedTimeNanos, TimeUnit.NANOSECONDS),
             timeUnit.toString().toLowerCase(),
-            taskDescription));
+            taskDescription);
+      } else {
+        return null;
+      }
+    }
+
+    @Override
+    public void accept(long elapsedTimeNanos) {
+      String logMessage = loggingMessage(elapsedTimeNanos);
+      if (logMessage != null) {
+        logger.info(logMessage);
       }
     }
   }