Use AutoProfiler in the Bazel codebase.

--
MOS_MIGRATED_REVID=102584924

7 files changed, 75 insertions, 98 deletions

diff --git a/src/main/java/com/google/devtools/build/lib/actions/ResourceManager.java b/src/main/java/com/google/devtools/build/lib/actions/ResourceManager.java
index 05be3370ea..04f42f6a15 100644
--- a/src/main/java/com/google/devtools/build/lib/actions/ResourceManager.java
+++ b/src/main/java/com/google/devtools/build/lib/actions/ResourceManager.java
@@ -14,11 +14,13 @@
 
 package com.google.devtools.build.lib.actions;
 
+import static com.google.devtools.build.lib.profiler.AutoProfiler.profiled;
+
 import com.google.common.annotations.VisibleForTesting;
 import com.google.common.base.Preconditions;
 import com.google.common.eventbus.EventBus;
 import com.google.devtools.build.lib.concurrent.ThreadSafety.ThreadSafe;
-import com.google.devtools.build.lib.profiler.Profiler;
+import com.google.devtools.build.lib.profiler.AutoProfiler;
 import com.google.devtools.build.lib.profiler.ProfilerTask;
 import com.google.devtools.build.lib.util.Pair;
 
@@ -178,7 +180,7 @@ public class ResourceManager {
   public void acquireResources(ActionMetadata owner, ResourceSet resources)
       throws InterruptedException {
     Preconditions.checkNotNull(resources);
-    long startTime = Profiler.nanoTimeMaybe();
+    AutoProfiler p = profiled(owner, ProfilerTask.ACTION_LOCK);
     CountDownLatch latch = null;
     try {
       waiting(owner);
@@ -193,7 +195,7 @@ public class ResourceManager {
 
       // Profile acquisition only if it waited for resource to become available.
       if (latch != null) {
-        Profiler.instance().logSimpleTask(startTime, ProfilerTask.ACTION_LOCK, owner);
+        p.complete();
       }
     }
   }
@@ -274,7 +276,7 @@ public class ResourceManager {
    */
   public void releaseResources(ActionMetadata owner, ResourceSet resources) {
     boolean isConflict = false;
-    long startTime = Profiler.nanoTimeMaybe();
+    AutoProfiler p = profiled(owner, ProfilerTask.ACTION_RELEASE);
     try {
       isConflict = release(resources);
     } finally {
@@ -282,7 +284,7 @@ public class ResourceManager {
 
       // Profile resource release only if it resolved at least one allocation request.
       if (isConflict) {
-        Profiler.instance().logSimpleTask(startTime, ProfilerTask.ACTION_RELEASE, owner);
+        p.complete();
       }
     }
   }
diff --git a/src/main/java/com/google/devtools/build/lib/buildtool/ExecutionTool.java b/src/main/java/com/google/devtools/build/lib/buildtool/ExecutionTool.java
index 8a9c9c3cd4..9c18133275 100644
--- a/src/main/java/com/google/devtools/build/lib/buildtool/ExecutionTool.java
+++ b/src/main/java/com/google/devtools/build/lib/buildtool/ExecutionTool.java
@@ -76,6 +76,7 @@ import com.google.devtools.build.lib.exec.OutputService;
 import com.google.devtools.build.lib.exec.SingleBuildFileCache;
 import com.google.devtools.build.lib.exec.SymlinkTreeStrategy;
 import com.google.devtools.build.lib.packages.Rule;
+import com.google.devtools.build.lib.profiler.AutoProfiler;
 import com.google.devtools.build.lib.profiler.ProfilePhase;
 import com.google.devtools.build.lib.profiler.Profiler;
 import com.google.devtools.build.lib.profiler.ProfilerTask;
@@ -89,7 +90,6 @@ import com.google.devtools.build.lib.skyframe.Builder;
 import com.google.devtools.build.lib.skyframe.SkyframeExecutor;
 import com.google.devtools.build.lib.syntax.Label;
 import com.google.devtools.build.lib.util.AbruptExitException;
-import com.google.devtools.build.lib.util.BlazeClock;
 import com.google.devtools.build.lib.util.ExitCode;
 import com.google.devtools.build.lib.util.LoggingUtil;
 import com.google.devtools.build.lib.util.io.OutErr;
@@ -472,11 +472,11 @@ public class ExecutionTool {
         saveCaches(actionCache);
       }
 
-      long startTime = Profiler.nanoTimeMaybe();
-      determineSuccessfulTargets(buildResult, configuredTargets, builtTargets, timer);
-      showBuildResult(request, buildResult, configuredTargets, analysisResult.getAspects());
-      Preconditions.checkNotNull(buildResult.getSuccessfulTargets());
-      Profiler.instance().logSimpleTask(startTime, ProfilerTask.INFO, "Show results");
+      try (AutoProfiler p = AutoProfiler.profiled("Show results", ProfilerTask.INFO)) {
+        determineSuccessfulTargets(buildResult, configuredTargets, builtTargets, timer);
+        showBuildResult(request, buildResult, configuredTargets, analysisResult.getAspects());
+        Preconditions.checkNotNull(buildResult.getSuccessfulTargets());
+      }
       if (explanationHandler != null) {
         uninstallExplanationHandler(explanationHandler);
       }
@@ -541,9 +541,7 @@ public class ExecutionTool {
    * Prepare for a local output build.
    */
   private void startLocalOutputBuild() throws ExecutorInitException {
-    long startTime = Profiler.nanoTimeMaybe();
-
-    try {
+    try (AutoProfiler p = AutoProfiler.profiled("Starting local output build", ProfilerTask.INFO)) {
       Path outputPath = runtime.getOutputPath();
       Path localOutputPath = runtime.getDirectories().getLocalOutputPath();
 
@@ -559,9 +557,6 @@ public class ExecutionTool {
           throw new ExecutorInitException("Couldn't handle local output directory symlinks", e);
         }
       }
-    } finally {
-      Profiler.instance().logSimpleTask(startTime, ProfilerTask.INFO,
-          "Starting local output build");
     }
   }
 
@@ -879,21 +874,14 @@ public class ExecutionTool {
     long actionCacheSizeInBytes = 0;
     long actionCacheSaveTime;
 
-    long startTime = BlazeClock.nanoTime();
+    AutoProfiler p = AutoProfiler.profiledAndLogged("Saving action cache", ProfilerTask.INFO, LOG);
     try {
-      LOG.info("saving action cache...");
       actionCacheSizeInBytes = actionCache.save();
-      LOG.info("action cache saved");
     } catch (IOException e) {
       getReporter().handle(Event.error("I/O error while writing action log: " + e.getMessage()));
     } finally {
-      long stopTime = BlazeClock.nanoTime();
-      actionCacheSaveTime =
-          TimeUnit.MILLISECONDS.convert(stopTime - startTime, TimeUnit.NANOSECONDS);
-      Profiler.instance().logSimpleTask(startTime, stopTime,
-                                        ProfilerTask.INFO, "Saving action cache");
+      actionCacheSaveTime = p.completeAndGetElapsedTimeNanos();
     }
-
     runtime.getEventBus().post(new CachesSavedEvent(
         actionCacheSaveTime, actionCacheSizeInBytes));
   }
diff --git a/src/main/java/com/google/devtools/build/lib/query2/AbstractBlazeQueryEnvironment.java b/src/main/java/com/google/devtools/build/lib/query2/AbstractBlazeQueryEnvironment.java
index 81c8f33670..94fc3f8eb1 100644
--- a/src/main/java/com/google/devtools/build/lib/query2/AbstractBlazeQueryEnvironment.java
+++ b/src/main/java/com/google/devtools/build/lib/query2/AbstractBlazeQueryEnvironment.java
@@ -29,7 +29,7 @@ import com.google.devtools.build.lib.pkgcache.PackageProvider;
 import com.google.devtools.build.lib.pkgcache.PathPackageLocator;
 import com.google.devtools.build.lib.pkgcache.TargetPatternEvaluator;
 import com.google.devtools.build.lib.pkgcache.TransitivePackageLoader;
-import com.google.devtools.build.lib.profiler.Profiler;
+import com.google.devtools.build.lib.profiler.AutoProfiler;
 import com.google.devtools.build.lib.query2.engine.QueryEnvironment;
 import com.google.devtools.build.lib.query2.engine.QueryEvalResult;
 import com.google.devtools.build.lib.query2.engine.QueryException;
@@ -137,29 +137,25 @@ public abstract class AbstractBlazeQueryEnvironment<T> implements QueryEnvironme
    */
   public QueryEvalResult<T> evaluateQuery(QueryExpression expr)
       throws QueryException, InterruptedException {
-    long startTime = Profiler.nanoTimeMaybe();
-    resolvedTargetPatterns.clear();
-
-    // In the --nokeep_going case, errors are reported in the order in which the patterns are
-    // specified; using a linked hash set here makes sure that the left-most error is reported.
-    Set<String> targetPatternSet = new LinkedHashSet<>();
-    expr.collectTargetPatterns(targetPatternSet);
-    try {
-      resolvedTargetPatterns.putAll(preloadOrThrow(expr, targetPatternSet));
-    } catch (TargetParsingException e) {
-      // Unfortunately, by evaluating the patterns in parallel, we lose some location information.
-      throw new QueryException(expr, e.getMessage());
-    }
-
     Set<T> resultNodes;
-    try {
-      resultNodes = expr.eval(this);
-    } catch (QueryException e) {
-      throw new QueryException(e, expr);
-    } finally {
-      long duration = Profiler.nanoTimeMaybe() - startTime;
-      if (duration > 0) {
-        LOG.info("Spent " + (duration / 1000 / 1000) + " ms evaluating query");
+    try (AutoProfiler p = AutoProfiler.logged("evaluating query", LOG)) {
+      resolvedTargetPatterns.clear();
+
+      // In the --nokeep_going case, errors are reported in the order in which the patterns are
+      // specified; using a linked hash set here makes sure that the left-most error is reported.
+      Set<String> targetPatternSet = new LinkedHashSet<>();
+      expr.collectTargetPatterns(targetPatternSet);
+      try {
+        resolvedTargetPatterns.putAll(preloadOrThrow(expr, targetPatternSet));
+      } catch (TargetParsingException e) {
+        // Unfortunately, by evaluating the patterns in parallel, we lose some location information.
+        throw new QueryException(expr, e.getMessage());
+      }
+
+      try {
+        resultNodes = expr.eval(this);
+      } catch (QueryException e) {
+        throw new QueryException(e, expr);
       }
     }
 
diff --git a/src/main/java/com/google/devtools/build/lib/runtime/BlazeRuntime.java b/src/main/java/com/google/devtools/build/lib/runtime/BlazeRuntime.java
index edd1b92602..7e4e41cc5b 100644
--- a/src/main/java/com/google/devtools/build/lib/runtime/BlazeRuntime.java
+++ b/src/main/java/com/google/devtools/build/lib/runtime/BlazeRuntime.java
@@ -14,6 +14,8 @@
 
 package com.google.devtools.build.lib.runtime;
 
+import static com.google.devtools.build.lib.profiler.AutoProfiler.profiled;
+import static com.google.devtools.build.lib.profiler.AutoProfiler.profiledAndLogged;
 import static java.nio.charset.StandardCharsets.ISO_8859_1;
 
 import com.google.common.annotations.VisibleForTesting;
@@ -64,6 +66,7 @@ import com.google.devtools.build.lib.pkgcache.LoadingPhaseRunner;
 import com.google.devtools.build.lib.pkgcache.PackageCacheOptions;
 import com.google.devtools.build.lib.pkgcache.PackageManager;
 import com.google.devtools.build.lib.pkgcache.TargetPatternEvaluator;
+import com.google.devtools.build.lib.profiler.AutoProfiler;
 import com.google.devtools.build.lib.profiler.MemoryProfiler;
 import com.google.devtools.build.lib.profiler.ProfilePhase;
 import com.google.devtools.build.lib.profiler.Profiler;
@@ -299,10 +302,9 @@ public final class BlazeRuntime {
     if (getOutputService() != null) {
       return getOutputService().getFilesSystemName();
     }
-    long startTime = Profiler.nanoTimeMaybe();
-    String fileSystem = FileSystemUtils.getFileSystem(getOutputBase());
-    Profiler.instance().logSimpleTask(startTime, ProfilerTask.INFO, "Finding output file system");
-    return fileSystem;
+    try (AutoProfiler p = profiled("Finding output file system", ProfilerTask.INFO)) {
+      return FileSystemUtils.getFileSystem(getOutputBase());
+    }
   }
 
   public String getOutputFileSystem() {
@@ -632,25 +634,19 @@ public final class BlazeRuntime {
         actionCache = new NullActionCache();
         return actionCache;
       }
-      long startTime = Profiler.nanoTimeMaybe();
-      try {
-        actionCache = new CompactPersistentActionCache(getCacheDirectory(), clock);
-      } catch (IOException e) {
-        LOG.log(Level.WARNING, "Failed to load action cache: " + e.getMessage(), e);
-        LoggingUtil.logToRemote(Level.WARNING, "Failed to load action cache: "
-            + e.getMessage(), e);
-        getReporter().handle(
-            Event.error("Error during action cache initialization: " + e.getMessage()
-            + ". Corrupted files were renamed to '" + getCacheDirectory() + "/*.bad'. "
-            + "Blaze will now reset action cache data, causing a full rebuild"));
-        actionCache = new CompactPersistentActionCache(getCacheDirectory(), clock);
-      } finally {
-        long stopTime = Profiler.nanoTimeMaybe();
-        long duration = stopTime - startTime;
-        if (duration > 0) {
-          LOG.info("Spent " + (duration / (1000 * 1000)) + " ms loading persistent action cache");
+      try (AutoProfiler p = profiledAndLogged("Loading action cache", ProfilerTask.INFO, LOG)) {
+        try {
+          actionCache = new CompactPersistentActionCache(getCacheDirectory(), clock);
+        } catch (IOException e) {
+          LOG.log(Level.WARNING, "Failed to load action cache: " + e.getMessage(), e);
+          LoggingUtil.logToRemote(Level.WARNING, "Failed to load action cache: "
+              + e.getMessage(), e);
+          getReporter().handle(
+              Event.error("Error during action cache initialization: " + e.getMessage()
+              + ". Corrupted files were renamed to '" + getCacheDirectory() + "/*.bad'. "
+              + "Blaze will now reset action cache data, causing a full rebuild"));
+          actionCache = new CompactPersistentActionCache(getCacheDirectory(), clock);
         }
-        Profiler.instance().logSimpleTask(startTime, ProfilerTask.INFO, "Loading action cache");
       }
     }
     return actionCache;
@@ -1506,6 +1502,7 @@ public final class BlazeRuntime {
     }
 
     BlazeRuntime runtime = runtimeBuilder.build();
+    AutoProfiler.setClock(runtime.getClock());
     BugReport.setRuntime(runtime);
     return runtime;
   }
diff --git a/src/main/java/com/google/devtools/build/lib/server/IdleServerTasks.java b/src/main/java/com/google/devtools/build/lib/server/IdleServerTasks.java
index ad3e475cb8..c1172828ad 100644
--- a/src/main/java/com/google/devtools/build/lib/server/IdleServerTasks.java
+++ b/src/main/java/com/google/devtools/build/lib/server/IdleServerTasks.java
@@ -15,6 +15,7 @@
 package com.google.devtools.build.lib.server;
 
 import com.google.common.base.Preconditions;
+import com.google.devtools.build.lib.profiler.AutoProfiler;
 import com.google.devtools.build.lib.util.LoggingUtil;
 import com.google.devtools.build.lib.util.ProcMeminfoParser;
 import com.google.devtools.build.lib.vfs.FileStatus;
@@ -59,9 +60,9 @@ class IdleServerTasks {
     // Do a GC cycle while the server is idle.
     executor.schedule(new Runnable() {
         @Override public void run() {
-          long before = System.currentTimeMillis();
-          System.gc();
-          LOG.info("Idle GC: " + (System.currentTimeMillis() - before) + "ms");
+          try (AutoProfiler p = AutoProfiler.logged("Idle GC", LOG)) {
+            System.gc();
+          }
         }
       }, 10, TimeUnit.SECONDS);
   }
diff --git a/src/main/java/com/google/devtools/build/lib/skyframe/SequencedSkyframeExecutor.java b/src/main/java/com/google/devtools/build/lib/skyframe/SequencedSkyframeExecutor.java
index fbbe90b28b..6461e3f085 100644
--- a/src/main/java/com/google/devtools/build/lib/skyframe/SequencedSkyframeExecutor.java
+++ b/src/main/java/com/google/devtools/build/lib/skyframe/SequencedSkyframeExecutor.java
@@ -38,7 +38,7 @@ import com.google.devtools.build.lib.packages.PackageFactory;
 import com.google.devtools.build.lib.packages.Preprocessor;
 import com.google.devtools.build.lib.pkgcache.PackageCacheOptions;
 import com.google.devtools.build.lib.pkgcache.PathPackageLocator;
-import com.google.devtools.build.lib.profiler.Profiler;
+import com.google.devtools.build.lib.profiler.AutoProfiler;
 import com.google.devtools.build.lib.skyframe.DirtinessCheckerUtils.BasicFilesystemDirtinessChecker;
 import com.google.devtools.build.lib.skyframe.DirtinessCheckerUtils.MissingDiffDirtinessChecker;
 import com.google.devtools.build.lib.skyframe.DirtinessCheckerUtils.UnionDirtinessChecker;
@@ -476,22 +476,19 @@ public final class SequencedSkyframeExecutor extends SkyframeExecutor {
    * recreate them if necessary).
    */
   private void discardAnalysisCache(Collection<ConfiguredTarget> topLevelTargets) {
-    long startTime = Profiler.nanoTimeMaybe();
-    lastAnalysisDiscarded = true;
-    for (Map.Entry<SkyKey, SkyValue> entry : memoizingEvaluator.getValues().entrySet()) {
-      if (!entry.getKey().functionName().equals(SkyFunctions.CONFIGURED_TARGET)) {
-        continue;
-      }
-      ConfiguredTargetValue ctValue = (ConfiguredTargetValue) entry.getValue();
-      // ctValue may be null if target was not successfully analyzed.
-      if (ctValue != null && !topLevelTargets.contains(ctValue.getConfiguredTarget())) {
-        ctValue.clear();
+    try (AutoProfiler p = AutoProfiler.logged("discarding analysis cache", LOG)) {
+      lastAnalysisDiscarded = true;
+      for (Map.Entry<SkyKey, SkyValue> entry : memoizingEvaluator.getValues().entrySet()) {
+        if (!entry.getKey().functionName().equals(SkyFunctions.CONFIGURED_TARGET)) {
+          continue;
+        }
+        ConfiguredTargetValue ctValue = (ConfiguredTargetValue) entry.getValue();
+        // ctValue may be null if target was not successfully analyzed.
+        if (ctValue != null && !topLevelTargets.contains(ctValue.getConfiguredTarget())) {
+          ctValue.clear();
+        }
       }
     }
-    long duration = Profiler.nanoTimeMaybe() - startTime;
-    if (duration > 0) {
-      LOG.info("Spent " + (duration / 1000 / 1000) + " ms discarding analysis cache");
-    }
   }
 
   @Override
diff --git a/src/main/java/com/google/devtools/build/lib/skyframe/SkyframeExecutor.java b/src/main/java/com/google/devtools/build/lib/skyframe/SkyframeExecutor.java
index 5fc379eb7e..050497fc64 100644
--- a/src/main/java/com/google/devtools/build/lib/skyframe/SkyframeExecutor.java
+++ b/src/main/java/com/google/devtools/build/lib/skyframe/SkyframeExecutor.java
@@ -84,7 +84,7 @@ import com.google.devtools.build.lib.pkgcache.PackageCacheOptions;
 import com.google.devtools.build.lib.pkgcache.PackageManager;
 import com.google.devtools.build.lib.pkgcache.PathPackageLocator;
 import com.google.devtools.build.lib.pkgcache.TransitivePackageLoader;
-import com.google.devtools.build.lib.profiler.Profiler;
+import com.google.devtools.build.lib.profiler.AutoProfiler;
 import com.google.devtools.build.lib.skyframe.AspectValue.AspectKey;
 import com.google.devtools.build.lib.skyframe.DirtinessCheckerUtils.FileDirtinessChecker;
 import com.google.devtools.build.lib.skyframe.SkyframeActionExecutor.ActionCompletedReceiver;
@@ -980,14 +980,10 @@ public abstract class SkyframeExecutor implements WalkableGraphFactory {
         || skyframeBuildView.isSomeConfiguredTargetInvalidated()) {
       // This operation is somewhat expensive, so we only do it if the graph might have changed in
       // some way -- either we analyzed a new target or we invalidated an old one.
-      long startTime = Profiler.nanoTimeMaybe();
-      skyframeActionExecutor.findAndStoreArtifactConflicts(getActionLookupValues());
-      skyframeBuildView.resetEvaluatedConfiguredTargetFlag();
-      // The invalidated configured targets flag will be reset later in the evaluate() call.
-
-      long duration = Profiler.nanoTimeMaybe() - startTime;
-      if (duration > 0) {
-        LOG.info("Spent " + (duration / 1000 / 1000) + " ms discovering artifact conflicts");
+      try (AutoProfiler p = AutoProfiler.logged("discovering artifact conflicts", LOG)) {
+        skyframeActionExecutor.findAndStoreArtifactConflicts(getActionLookupValues());
+        skyframeBuildView.resetEvaluatedConfiguredTargetFlag();
+        // The invalidated configured targets flag will be reset later in the evaluate() call.
       }
     }
     return skyframeActionExecutor.badActions();