Add AutoProfiler-like API to Profiler
- migrate all startTask/completeTask pairs to the new API
PiperOrigin-RevId: 200038703
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 8b3d866..a149b1a 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
@@ -67,6 +67,7 @@
import com.google.devtools.build.lib.profiler.ProfilePhase;
import com.google.devtools.build.lib.profiler.Profiler;
import com.google.devtools.build.lib.profiler.ProfilerTask;
+import com.google.devtools.build.lib.profiler.SilentCloseable;
import com.google.devtools.build.lib.runtime.BlazeModule;
import com.google.devtools.build.lib.runtime.BlazeRuntime;
import com.google.devtools.build.lib.runtime.CommandEnvironment;
@@ -369,7 +370,7 @@
env.getEventBus()
.post(new ExecutionPhaseCompleteEvent(timer.stop().elapsed(TimeUnit.MILLISECONDS)));
- try (AutoProfiler p = AutoProfiler.profiled("Show results", ProfilerTask.INFO)) {
+ try (SilentCloseable c = Profiler.instance().profile(ProfilerTask.INFO, "Show results")) {
buildResult.setSuccessfulTargets(
determineSuccessfulTargets(configuredTargets, builtTargets));
buildResult.setSuccessfulAspects(determineSuccessfulAspects(aspects, builtAspects));
@@ -379,7 +380,7 @@
analysisResult.getTargetsToSkip(), analysisResult.getAspects());
}
- try (AutoProfiler p = AutoProfiler.profiled("Show artifacts", ProfilerTask.INFO)) {
+ try (SilentCloseable c = Profiler.instance().profile(ProfilerTask.INFO, "Show artifacts")) {
if (request.getBuildOptions().showArtifacts) {
BuildResultPrinter buildResultPrinter = new BuildResultPrinter(env);
buildResultPrinter.showArtifacts(
@@ -444,7 +445,8 @@
* Prepare for a local output build.
*/
private void startLocalOutputBuild() throws ExecutorInitException {
- try (AutoProfiler p = AutoProfiler.profiled("Starting local output build", ProfilerTask.INFO)) {
+ try (SilentCloseable c =
+ Profiler.instance().profile(ProfilerTask.INFO, "Starting local output build")) {
Path outputPath = env.getDirectories().getOutputPath(env.getWorkspaceName());
Path localOutputPath = env.getDirectories().getLocalOutputPath();
diff --git a/src/main/java/com/google/devtools/build/lib/exec/BlazeExecutor.java b/src/main/java/com/google/devtools/build/lib/exec/BlazeExecutor.java
index afd0448..5786a48 100644
--- a/src/main/java/com/google/devtools/build/lib/exec/BlazeExecutor.java
+++ b/src/main/java/com/google/devtools/build/lib/exec/BlazeExecutor.java
@@ -24,8 +24,6 @@
import com.google.devtools.build.lib.events.EventHandler;
import com.google.devtools.build.lib.events.ExtendedEventHandler;
import com.google.devtools.build.lib.events.Reporter;
-import com.google.devtools.build.lib.profiler.Profiler;
-import com.google.devtools.build.lib.profiler.ProfilerTask;
import com.google.devtools.build.lib.vfs.FileSystem;
import com.google.devtools.build.lib.vfs.Path;
import com.google.devtools.common.options.OptionsClassProvider;
@@ -135,8 +133,6 @@
*/
public void executionPhaseStarting() {
Preconditions.checkState(!inExecutionPhase.getAndSet(true));
- Profiler.instance().startTask(ProfilerTask.INFO, "Initializing executors");
- Profiler.instance().completeTask(ProfilerTask.INFO);
}
/**
@@ -147,9 +143,6 @@
if (!inExecutionPhase.get()) {
return;
}
-
- Profiler.instance().startTask(ProfilerTask.INFO, "Shutting down executors");
- Profiler.instance().completeTask(ProfilerTask.INFO);
inExecutionPhase.set(false);
}
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 a181cce..b5fa838 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
@@ -58,7 +58,7 @@
* }
* </pre>
*/
-public class AutoProfiler implements AutoCloseable {
+public class AutoProfiler implements SilentCloseable {
private static final AtomicReference<Clock> CLOCK_REF = new AtomicReference<>(null);
private static final AtomicReference<LoggingElapsedTimeReceiverFactory>
LOGGING_ELAPSED_TIME_RECEIVER_FACTORY_REF = new AtomicReference<>(
diff --git a/src/main/java/com/google/devtools/build/lib/profiler/Profiler.java b/src/main/java/com/google/devtools/build/lib/profiler/Profiler.java
index 69da2de..0bf0e41 100644
--- a/src/main/java/com/google/devtools/build/lib/profiler/Profiler.java
+++ b/src/main/java/com/google/devtools/build/lib/profiler/Profiler.java
@@ -806,17 +806,26 @@
}
/**
- * Records the beginning of the task specified by the parameters. This method should always be
- * followed by completeTask() invocation to mark the end of task execution (usually ensured by try
- * {} finally {} block). Failure to do so will result in task stack corruption.
+ * Records the beginning of a task as specified, and returns a {@link SilentCloseable} instance
+ * that ends the task. This lets the system do the work of ending the task, with the compiler
+ * giving a warning if the returned instance is not closed.
*
* <p>Use of this method allows to support nested task monitoring. For tasks that are known to not
* have any subtasks, logSimpleTask() should be used instead.
*
+ * <p>Use like this:
+ * <pre>
+ * {@code
+ * try (SilentCloseable c = Profiler.instance().profile(type, "description")) {
+ * // Your code here.
+ * }
+ * }
+ * </pre>
+ *
* @param type predefined task type - see ProfilerTask for available types.
* @param description task description. May be stored until the end of the build.
*/
- public void startTask(ProfilerTask type, String description) {
+ public SilentCloseable profile(ProfilerTask type, String description) {
// ProfilerInfo.allTasksById is supposed to be an id -> Task map, but it is in fact a List,
// which means that we cannot drop tasks to which we had already assigned ids. Therefore,
// non-leaf tasks must not have a minimum duration. However, we don't quite consistently
@@ -825,6 +834,9 @@
Preconditions.checkNotNull(description);
if (isActive() && isProfiling(type)) {
taskStack.push(type, description);
+ return () -> completeTask(type);
+ } else {
+ return () -> {};
}
}
@@ -835,7 +847,7 @@
*
* @param type task type.
*/
- public void completeTask(ProfilerTask type) {
+ private void completeTask(ProfilerTask type) {
if (isActive() && isProfiling(type)) {
long endTime = clock.nanoTime();
TaskData data = taskStack.pop();
diff --git a/src/main/java/com/google/devtools/build/lib/profiler/SilentCloseable.java b/src/main/java/com/google/devtools/build/lib/profiler/SilentCloseable.java
new file mode 100644
index 0000000..81c65fe
--- /dev/null
+++ b/src/main/java/com/google/devtools/build/lib/profiler/SilentCloseable.java
@@ -0,0 +1,22 @@
+// Copyright 2018 The Bazel Authors. All rights reserved.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+package com.google.devtools.build.lib.profiler;
+
+/**
+ * An {@link AutoCloseable} sub-interface that declares no exceptions thrown.
+ */
+public interface SilentCloseable extends AutoCloseable {
+ @Override
+ void close();
+}
diff --git a/src/main/java/com/google/devtools/build/lib/rules/cpp/CppCompileAction.java b/src/main/java/com/google/devtools/build/lib/rules/cpp/CppCompileAction.java
index 9c7e837..3c541e8 100644
--- a/src/main/java/com/google/devtools/build/lib/rules/cpp/CppCompileAction.java
+++ b/src/main/java/com/google/devtools/build/lib/rules/cpp/CppCompileAction.java
@@ -53,6 +53,7 @@
import com.google.devtools.build.lib.events.Event;
import com.google.devtools.build.lib.profiler.Profiler;
import com.google.devtools.build.lib.profiler.ProfilerTask;
+import com.google.devtools.build.lib.profiler.SilentCloseable;
import com.google.devtools.build.lib.rules.cpp.CcCommon.CoptsFilter;
import com.google.devtools.build.lib.rules.cpp.CcToolchainFeatures.FeatureConfiguration;
import com.google.devtools.build.lib.rules.cpp.CppCompileActionContext.Reply;
@@ -923,14 +924,11 @@
@ThreadCompatible
public final void updateActionInputs(NestedSet<Artifact> discoveredInputs) {
NestedSetBuilder<Artifact> inputs = NestedSetBuilder.stableOrder();
- Profiler.instance().startTask(ProfilerTask.ACTION_UPDATE, describe());
- try {
+ try (SilentCloseable c = Profiler.instance().profile(ProfilerTask.ACTION_UPDATE, describe())) {
inputs.addTransitive(mandatoryInputs);
inputs.addAll(inputsForInvalidation);
inputs.addTransitive(discoveredInputs);
updateInputs(inputs.build());
- } finally {
- Profiler.instance().completeTask(ProfilerTask.ACTION_UPDATE);
}
}
diff --git a/src/main/java/com/google/devtools/build/lib/rules/cpp/IncludeScanner.java b/src/main/java/com/google/devtools/build/lib/rules/cpp/IncludeScanner.java
index 957a873..d6d46df 100644
--- a/src/main/java/com/google/devtools/build/lib/rules/cpp/IncludeScanner.java
+++ b/src/main/java/com/google/devtools/build/lib/rules/cpp/IncludeScanner.java
@@ -24,6 +24,7 @@
import com.google.devtools.build.lib.actions.UserExecException;
import com.google.devtools.build.lib.profiler.Profiler;
import com.google.devtools.build.lib.profiler.ProfilerTask;
+import com.google.devtools.build.lib.profiler.SilentCloseable;
import com.google.devtools.build.lib.vfs.FileSystemUtils;
import com.google.devtools.build.lib.vfs.PathFragment;
import java.io.IOException;
@@ -109,9 +110,7 @@
includes.addAll(action.getBuiltInIncludeFiles());
Profiler profiler = Profiler.instance();
- try {
- profiler.startTask(ProfilerTask.SCANNER, profilerTaskName);
-
+ try (SilentCloseable c = profiler.profile(ProfilerTask.SCANNER, profilerTaskName)) {
// We need to scan the action itself, but also the auxiliary scannables
// (for LIPO). There is no need to call getAuxiliaryScannables
// recursively.
@@ -148,8 +147,6 @@
}
} catch (IOException e) {
throw new EnvironmentalExecException(e.getMessage());
- } finally {
- profiler.completeTask(ProfilerTask.SCANNER);
}
// Collect inputs and output
diff --git a/src/main/java/com/google/devtools/build/lib/runtime/BuildSummaryStatsModule.java b/src/main/java/com/google/devtools/build/lib/runtime/BuildSummaryStatsModule.java
index 4d2cdce..86f1147 100644
--- a/src/main/java/com/google/devtools/build/lib/runtime/BuildSummaryStatsModule.java
+++ b/src/main/java/com/google/devtools/build/lib/runtime/BuildSummaryStatsModule.java
@@ -30,6 +30,7 @@
import com.google.devtools.build.lib.exec.ExecutorBuilder;
import com.google.devtools.build.lib.profiler.Profiler;
import com.google.devtools.build.lib.profiler.ProfilerTask;
+import com.google.devtools.build.lib.profiler.SilentCloseable;
import com.google.devtools.build.lib.util.Pair;
import com.google.protobuf.ByteString;
import java.time.Duration;
@@ -101,27 +102,29 @@
String.format("%f", event.getResult().getElapsedSeconds()))));
if (criticalPathComputer != null) {
- Profiler.instance().startTask(ProfilerTask.CRITICAL_PATH, "Critical path");
- AggregatedCriticalPath<SimpleCriticalPathComponent> criticalPath =
- criticalPathComputer.aggregate();
- items.add(criticalPath.toStringSummary());
- statistics.add(Pair.of("critical path", ByteString.copyFromUtf8(criticalPath.toString())));
- logger.info(criticalPath.toString());
- logger.info(
- "Slowest actions:\n "
- + Joiner.on("\n ").join(criticalPathComputer.getSlowestComponents()));
- // We reverse the critical path because the profiler expect events ordered by the time
- // when the actions were executed while critical path computation is stored in the reverse
- // way.
- for (SimpleCriticalPathComponent stat : criticalPath.components().reverse()) {
- Profiler.instance()
- .logSimpleTaskDuration(
- stat.getStartNanos(),
- Duration.ofNanos(stat.getElapsedTimeNanos()),
- ProfilerTask.CRITICAL_PATH_COMPONENT,
- stat.prettyPrintAction());
+ try (SilentCloseable c =
+ Profiler.instance().profile(ProfilerTask.CRITICAL_PATH, "Critical path")) {
+ AggregatedCriticalPath<SimpleCriticalPathComponent> criticalPath =
+ criticalPathComputer.aggregate();
+ items.add(criticalPath.toStringSummary());
+ statistics.add(
+ Pair.of("critical path", ByteString.copyFromUtf8(criticalPath.toString())));
+ logger.info(criticalPath.toString());
+ logger.info(
+ "Slowest actions:\n "
+ + Joiner.on("\n ").join(criticalPathComputer.getSlowestComponents()));
+ // We reverse the critical path because the profiler expect events ordered by the time
+ // when the actions were executed while critical path computation is stored in the reverse
+ // way.
+ for (SimpleCriticalPathComponent stat : criticalPath.components().reverse()) {
+ Profiler.instance()
+ .logSimpleTaskDuration(
+ stat.getStartNanos(),
+ Duration.ofNanos(stat.getElapsedTimeNanos()),
+ ProfilerTask.CRITICAL_PATH_COMPONENT,
+ stat.prettyPrintAction());
+ }
}
- Profiler.instance().completeTask(ProfilerTask.CRITICAL_PATH);
}
reporter.handle(Event.info(Joiner.on(", ").join(items)));
diff --git a/src/main/java/com/google/devtools/build/lib/runtime/CommandEnvironment.java b/src/main/java/com/google/devtools/build/lib/runtime/CommandEnvironment.java
index 22ef333..2ad145d 100644
--- a/src/main/java/com/google/devtools/build/lib/runtime/CommandEnvironment.java
+++ b/src/main/java/com/google/devtools/build/lib/runtime/CommandEnvironment.java
@@ -14,8 +14,6 @@
package com.google.devtools.build.lib.runtime;
-import static com.google.devtools.build.lib.profiler.AutoProfiler.profiled;
-
import com.google.common.base.Preconditions;
import com.google.common.eventbus.EventBus;
import com.google.devtools.build.lib.actions.PackageRootResolver;
@@ -34,8 +32,9 @@
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.Profiler;
import com.google.devtools.build.lib.profiler.ProfilerTask;
+import com.google.devtools.build.lib.profiler.SilentCloseable;
import com.google.devtools.build.lib.runtime.proto.InvocationPolicyOuterClass.InvocationPolicy;
import com.google.devtools.build.lib.skyframe.OutputService;
import com.google.devtools.build.lib.skyframe.SkyframeBuildView;
@@ -640,7 +639,8 @@
// and so we need to compute it freshly. Otherwise, we can used the immutable value that's
// precomputed by our BlazeWorkspace.
if (getOutputService() != null) {
- try (AutoProfiler p = profiled("Finding output file system", ProfilerTask.INFO)) {
+ try (SilentCloseable c =
+ Profiler.instance().profile(ProfilerTask.INFO, "Finding output file system")) {
return getOutputService().getFilesSystemName();
}
}
diff --git a/src/main/java/com/google/devtools/build/lib/skyframe/ActionFileSystem.java b/src/main/java/com/google/devtools/build/lib/skyframe/ActionFileSystem.java
index fb4ead3..6fe598d 100644
--- a/src/main/java/com/google/devtools/build/lib/skyframe/ActionFileSystem.java
+++ b/src/main/java/com/google/devtools/build/lib/skyframe/ActionFileSystem.java
@@ -35,6 +35,7 @@
import com.google.devtools.build.lib.actions.MetadataProvider;
import com.google.devtools.build.lib.profiler.Profiler;
import com.google.devtools.build.lib.profiler.ProfilerTask;
+import com.google.devtools.build.lib.profiler.SilentCloseable;
import com.google.devtools.build.lib.vfs.FileStatus;
import com.google.devtools.build.lib.vfs.FileSystem;
import com.google.devtools.build.lib.vfs.Path;
@@ -100,8 +101,8 @@
ActionInputMap inputArtifactData,
Iterable<Artifact> allowedInputs,
Iterable<Artifact> outputArtifacts) {
- try {
- Profiler.instance().startTask(ProfilerTask.ACTION_FS_STAGING, "staging");
+ try (SilentCloseable c =
+ Profiler.instance().profile(ProfilerTask.ACTION_FS_STAGING, "staging")) {
this.delegate = delegate;
this.execRootFragment = execRoot.asFragment();
@@ -133,8 +134,6 @@
.collect(ImmutableMap.toImmutableMap(Artifact::getExecPath, a -> a));
this.outputs = CacheBuilder.newBuilder().build(
CacheLoader.from(path -> new OutputMetadata(outputsMapping.get(path))));
- } finally {
- Profiler.instance().completeTask(ProfilerTask.ACTION_FS_STAGING);
}
}
diff --git a/src/main/java/com/google/devtools/build/lib/skyframe/PackageFunction.java b/src/main/java/com/google/devtools/build/lib/skyframe/PackageFunction.java
index 635040e..05189fb 100644
--- a/src/main/java/com/google/devtools/build/lib/skyframe/PackageFunction.java
+++ b/src/main/java/com/google/devtools/build/lib/skyframe/PackageFunction.java
@@ -51,6 +51,7 @@
import com.google.devtools.build.lib.packages.Target;
import com.google.devtools.build.lib.profiler.Profiler;
import com.google.devtools.build.lib.profiler.ProfilerTask;
+import com.google.devtools.build.lib.profiler.SilentCloseable;
import com.google.devtools.build.lib.skyframe.GlobValue.InvalidGlobPatternException;
import com.google.devtools.build.lib.skyframe.SkylarkImportLookupFunction.SkylarkImportFailedException;
import com.google.devtools.build.lib.syntax.BuildFileAST;
@@ -1177,11 +1178,11 @@
throws InterruptedException, PackageFunctionException {
LoadedPackageCacheEntry packageCacheEntry = packageFunctionCache.getIfPresent(packageId);
if (packageCacheEntry == null) {
- profiler.startTask(ProfilerTask.CREATE_PACKAGE, packageId.toString());
if (packageProgress != null) {
packageProgress.startReadPackage(packageId);
}
- try {
+ try (SilentCloseable c =
+ Profiler.instance().profile(ProfilerTask.CREATE_PACKAGE, packageId.toString())) {
AstParseResult astParseResult = astCache.getIfPresent(packageId);
if (astParseResult == null) {
if (showLoadingProgress.get()) {
@@ -1267,8 +1268,6 @@
packageProgress.doneReadPackage(packageId);
}
packageFunctionCache.put(packageId, packageCacheEntry);
- } finally {
- profiler.completeTask(ProfilerTask.CREATE_PACKAGE);
}
}
return packageCacheEntry;
diff --git a/src/main/java/com/google/devtools/build/lib/skyframe/SkyframeActionExecutor.java b/src/main/java/com/google/devtools/build/lib/skyframe/SkyframeActionExecutor.java
index bdff840..bcf26a7 100644
--- a/src/main/java/com/google/devtools/build/lib/skyframe/SkyframeActionExecutor.java
+++ b/src/main/java/com/google/devtools/build/lib/skyframe/SkyframeActionExecutor.java
@@ -76,6 +76,7 @@
import com.google.devtools.build.lib.events.Reporter;
import com.google.devtools.build.lib.profiler.Profiler;
import com.google.devtools.build.lib.profiler.ProfilerTask;
+import com.google.devtools.build.lib.profiler.SilentCloseable;
import com.google.devtools.build.lib.util.Pair;
import com.google.devtools.build.lib.util.io.FileOutErr;
import com.google.devtools.build.lib.util.io.OutErr;
@@ -546,11 +547,16 @@
long actionStartTime,
Iterable<Artifact> resolvedCacheArtifacts,
Map<String, String> clientEnv) {
- startProfileAction(ProfilerTask.ACTION_CHECK, action);
- Token token =
- actionCacheChecker.getTokenIfNeedToExecute(
- action, resolvedCacheArtifacts, clientEnv, explain ? reporter : null, metadataHandler);
- profiler.completeTask(ProfilerTask.ACTION_CHECK);
+ Token token;
+ try (SilentCloseable c = profiler.profile(ProfilerTask.ACTION_CHECK, action.describe())) {
+ token =
+ actionCacheChecker.getTokenIfNeedToExecute(
+ action,
+ resolvedCacheArtifacts,
+ clientEnv,
+ explain ? reporter : null,
+ metadataHandler);
+ }
if (token == null) {
boolean eventPosted = false;
// Notify BlazeRuntimeStatistics about the action middleman 'execution'.
@@ -702,10 +708,6 @@
this.actionInputPrefetcher = actionInputPrefetcher;
}
- private void startProfileAction(ProfilerTask task, Action action) {
- profiler.startTask(task, action.describe());
- }
-
private class ActionRunner implements Callable<ActionExecutionValue> {
private final ExtendedEventHandler eventHandler;
private final Action action;
@@ -731,8 +733,7 @@
@Override
public ActionExecutionValue call() throws ActionExecutionException, InterruptedException {
- startProfileAction(ProfilerTask.ACTION, action);
- try {
+ try (SilentCloseable c = profiler.profile(ProfilerTask.ACTION, action.describe())) {
if (actionCacheChecker.isActionExecutionProhibited(action)) {
// We can't execute an action (e.g. because --check_???_up_to_date option was used). Fail
// the build instead.
@@ -766,8 +767,6 @@
metadataHandler.getOutputTreeArtifactData(),
metadataHandler.getAdditionalOutputData(),
actionExecutionContext.getOutputSymlinks());
- } finally {
- profiler.completeTask(ProfilerTask.ACTION);
}
}
}
@@ -960,12 +959,11 @@
Action action,
ActionExecutionContext actionExecutionContext)
throws ActionExecutionException, InterruptedException {
- startProfileAction(ProfilerTask.ACTION_EXECUTE, action);
// ActionExecutionExceptions that occur as the thread is interrupted are
// assumed to be a result of that, so we throw InterruptedException
// instead.
FileOutErr outErrBuffer = actionExecutionContext.getFileOutErr();
- try {
+ try (SilentCloseable c = profiler.profile(ProfilerTask.ACTION_EXECUTE, action.describe())) {
ActionResult actionResult = action.execute(actionExecutionContext);
if (actionResult != ActionResult.EMPTY) {
eventHandler.post(new ActionResultReceivedEvent(action, actionResult));
@@ -983,8 +981,6 @@
// Defer reporting action success until outputs are checked
} catch (ActionExecutionException e) {
throw processAndThrow(eventHandler, e, action, outErrBuffer, ErrorTiming.AFTER_EXECUTION);
- } finally {
- profiler.completeTask(ProfilerTask.ACTION_EXECUTE);
}
return false;
}
@@ -999,14 +995,11 @@
Preconditions.checkState(action.inputsDiscovered(),
"Action %s successfully executed, but inputs still not known", action);
- startProfileAction(ProfilerTask.ACTION_COMPLETE, action);
- try {
+ try (SilentCloseable c = profiler.profile(ProfilerTask.ACTION_COMPLETE, action.describe())) {
if (!checkOutputs(action, metadataHandler)) {
reportError("not all outputs were created or valid", null, action,
outputAlreadyDumped ? null : fileOutErr);
}
- } finally {
- profiler.completeTask(ProfilerTask.ACTION_COMPLETE);
}
if (outputService != null) {
diff --git a/src/main/java/com/google/devtools/build/lib/syntax/BuiltinCallable.java b/src/main/java/com/google/devtools/build/lib/syntax/BuiltinCallable.java
index 8419e7f..27bf364 100644
--- a/src/main/java/com/google/devtools/build/lib/syntax/BuiltinCallable.java
+++ b/src/main/java/com/google/devtools/build/lib/syntax/BuiltinCallable.java
@@ -18,6 +18,7 @@
import com.google.devtools.build.lib.events.Location;
import com.google.devtools.build.lib.profiler.Profiler;
import com.google.devtools.build.lib.profiler.ProfilerTask;
+import com.google.devtools.build.lib.profiler.SilentCloseable;
import com.google.devtools.build.lib.skylarkinterface.SkylarkCallable;
import com.google.devtools.build.lib.syntax.Environment.LexicalFrame;
import com.google.devtools.build.lib.syntax.FuncallExpression.MethodDescriptor;
@@ -123,14 +124,12 @@
index++;
}
- Profiler.instance().startTask(ProfilerTask.SKYLARK_BUILTIN_FN, getName());
-
- try {
+ try (SilentCloseable c =
+ Profiler.instance().profile(ProfilerTask.SKYLARK_BUILTIN_FN, getName())) {
env.enterScope(this, SHARED_LEXICAL_FRAME_FOR_BUILTIN_METHOD_CALLS, ast, env.getGlobals());
return FuncallExpression.callMethod(
descriptor, getName(), obj, args, ast.getLocation(), env);
} finally {
- Profiler.instance().completeTask(ProfilerTask.SKYLARK_BUILTIN_FN);
env.exitScope();
}
}
diff --git a/src/main/java/com/google/devtools/build/lib/syntax/BuiltinFunction.java b/src/main/java/com/google/devtools/build/lib/syntax/BuiltinFunction.java
index 10a14a6..03d24bd 100644
--- a/src/main/java/com/google/devtools/build/lib/syntax/BuiltinFunction.java
+++ b/src/main/java/com/google/devtools/build/lib/syntax/BuiltinFunction.java
@@ -18,6 +18,7 @@
import com.google.devtools.build.lib.events.Location;
import com.google.devtools.build.lib.profiler.Profiler;
import com.google.devtools.build.lib.profiler.ProfilerTask;
+import com.google.devtools.build.lib.profiler.SilentCloseable;
import com.google.devtools.build.lib.skylarkinterface.SkylarkPrinter;
import com.google.devtools.build.lib.skylarkinterface.SkylarkSignature;
import com.google.devtools.build.lib.syntax.Environment.LexicalFrame;
@@ -166,9 +167,9 @@
}
}
- Profiler.instance().startTask(ProfilerTask.SKYLARK_BUILTIN_FN, getName());
// Last but not least, actually make an inner call to the function with the resolved arguments.
- try {
+ try (SilentCloseable c =
+ Profiler.instance().profile(ProfilerTask.SKYLARK_BUILTIN_FN, getName())) {
env.enterScope(this, SHARED_LEXICAL_FRAME_FOR_BUILTIN_FUNCTION_CALLS, ast, env.getGlobals());
return invokeMethod.invoke(this, args);
} catch (InvocationTargetException x) {
@@ -208,7 +209,6 @@
} catch (IllegalAccessException e) {
throw badCallException(loc, e, args);
} finally {
- Profiler.instance().completeTask(ProfilerTask.SKYLARK_BUILTIN_FN);
env.exitScope();
}
}
diff --git a/src/main/java/com/google/devtools/build/lib/syntax/UserDefinedFunction.java b/src/main/java/com/google/devtools/build/lib/syntax/UserDefinedFunction.java
index 4db184e..a892bda 100644
--- a/src/main/java/com/google/devtools/build/lib/syntax/UserDefinedFunction.java
+++ b/src/main/java/com/google/devtools/build/lib/syntax/UserDefinedFunction.java
@@ -18,6 +18,7 @@
import com.google.devtools.build.lib.events.Location;
import com.google.devtools.build.lib.profiler.Profiler;
import com.google.devtools.build.lib.profiler.ProfilerTask;
+import com.google.devtools.build.lib.profiler.SilentCloseable;
import com.google.devtools.build.lib.skylarkinterface.SkylarkPrinter;
import com.google.devtools.build.lib.syntax.Environment.LexicalFrame;
@@ -66,8 +67,7 @@
ImmutableList<String> names = signature.getSignature().getNames();
LexicalFrame lexicalFrame =
LexicalFrame.createForUserDefinedFunctionCall(env.mutability(), /*numArgs=*/ names.size());
- try {
- Profiler.instance().startTask(ProfilerTask.SKYLARK_USER_FN, getName());
+ try (SilentCloseable c = Profiler.instance().profile(ProfilerTask.SKYLARK_USER_FN, getName())) {
env.enterScope(this, lexicalFrame, ast, definitionGlobals);
// Registering the functions's arguments as variables in the local Environment
@@ -96,7 +96,6 @@
}
return Runtime.NONE;
} finally {
- Profiler.instance().completeTask(ProfilerTask.SKYLARK_USER_FN);
env.exitScope();
}
}
diff --git a/src/main/java/com/google/devtools/build/lib/vfs/UnixGlob.java b/src/main/java/com/google/devtools/build/lib/vfs/UnixGlob.java
index c70270c..24cdeae 100644
--- a/src/main/java/com/google/devtools/build/lib/vfs/UnixGlob.java
+++ b/src/main/java/com/google/devtools/build/lib/vfs/UnixGlob.java
@@ -35,6 +35,7 @@
import com.google.common.util.concurrent.Uninterruptibles;
import com.google.devtools.build.lib.profiler.Profiler;
import com.google.devtools.build.lib.profiler.ProfilerTask;
+import com.google.devtools.build.lib.profiler.SilentCloseable;
import java.io.IOException;
import java.util.Collection;
import java.util.Collections;
@@ -606,8 +607,8 @@
new Runnable() {
@Override
public void run() {
- Profiler.instance().startTask(ProfilerTask.VFS_GLOB, base.getPathString());
- try {
+ try (SilentCloseable c =
+ Profiler.instance().profile(ProfilerTask.VFS_GLOB, base.getPathString())) {
reallyGlob(base, baseIsDir, idx, context);
} catch (IOException e) {
ioException.set(e);
@@ -615,8 +616,6 @@
runtimeException.set(e);
} catch (Error e) {
error.set(e);
- } finally {
- Profiler.instance().completeTask(ProfilerTask.VFS_GLOB);
}
}
diff --git a/src/main/java/com/google/devtools/build/skyframe/AbstractExceptionalParallelEvaluator.java b/src/main/java/com/google/devtools/build/skyframe/AbstractExceptionalParallelEvaluator.java
index 7771d83..9d7bf27 100644
--- a/src/main/java/com/google/devtools/build/skyframe/AbstractExceptionalParallelEvaluator.java
+++ b/src/main/java/com/google/devtools/build/skyframe/AbstractExceptionalParallelEvaluator.java
@@ -22,6 +22,7 @@
import com.google.devtools.build.lib.events.ExtendedEventHandler;
import com.google.devtools.build.lib.profiler.Profiler;
import com.google.devtools.build.lib.profiler.ProfilerTask;
+import com.google.devtools.build.lib.profiler.SilentCloseable;
import com.google.devtools.build.lib.util.GroupedList;
import com.google.devtools.build.skyframe.EvaluationProgressReceiver.EvaluationState;
import com.google.devtools.build.skyframe.EvaluationProgressReceiver.EvaluationSuccessState;
@@ -211,11 +212,9 @@
}
}
- Profiler.instance().startTask(ProfilerTask.SKYFRAME_EVAL, "Parallel Evaluator evaluation");
- try {
+ try (SilentCloseable c =
+ Profiler.instance().profile(ProfilerTask.SKYFRAME_EVAL, "Parallel Evaluator evaluation")) {
return doMutatingEvaluation(skyKeySet);
- } finally {
- Profiler.instance().completeTask(ProfilerTask.SKYFRAME_EVAL);
}
}
diff --git a/src/test/java/com/google/devtools/build/lib/profiler/ProfilerChartTest.java b/src/test/java/com/google/devtools/build/lib/profiler/ProfilerChartTest.java
index e27ae16..105afb0 100644
--- a/src/test/java/com/google/devtools/build/lib/profiler/ProfilerChartTest.java
+++ b/src/test/java/com/google/devtools/build/lib/profiler/ProfilerChartTest.java
@@ -55,8 +55,7 @@
Runnable run = new Runnable() {
@Override
public void run() {
- Profiler.instance().startTask(ProfilerTask.ACTION, "action");
- Profiler.instance().completeTask(ProfilerTask.ACTION);
+ Profiler.instance().profile(ProfilerTask.ACTION, "action").close();
}
};
int threads = 4; // there is one extra thread due due the event that finalizes the profiler
@@ -79,11 +78,11 @@
@Override
public void run() {
Profiler profiler = Profiler.instance();
- profiler.startTask(ProfilerTask.ACTION, "action"); // Stays
- task(profiler, ProfilerTask.REMOTE_EXECUTION, "remote execution"); // Removed
- task(profiler, ProfilerTask.ACTION_CHECK, "check"); // Removed
- task(profiler, ProfilerTask.ACTION_LOCK, "lock"); // Stays
- profiler.completeTask(ProfilerTask.ACTION);
+ try (SilentCloseable c = profiler.profile(ProfilerTask.ACTION, "action")) { // Stays
+ task(profiler, ProfilerTask.REMOTE_EXECUTION, "remote execution"); // Removed
+ task(profiler, ProfilerTask.ACTION_CHECK, "check"); // Removed
+ task(profiler, ProfilerTask.ACTION_LOCK, "lock"); // Stays
+ }
task(profiler, ProfilerTask.INFO, "info"); // Stays
task(profiler, ProfilerTask.VFS_STAT, "stat"); // Stays, if showVFS
task(profiler, ProfilerTask.WAIT, "wait"); // Stays
@@ -264,13 +263,11 @@
}
private void task(final Profiler profiler, ProfilerTask task, String name) {
- profiler.startTask(task, name);
- try {
+ try (SilentCloseable c = profiler.profile(task, name)) {
Thread.sleep(100);
} catch (InterruptedException e) {
// ignore
}
- profiler.completeTask(task);
}
private static final class TestingChartVisitor implements ChartVisitor {
diff --git a/src/test/java/com/google/devtools/build/lib/profiler/ProfilerTest.java b/src/test/java/com/google/devtools/build/lib/profiler/ProfilerTest.java
index fc6853a..ae1d572 100644
--- a/src/test/java/com/google/devtools/build/lib/profiler/ProfilerTest.java
+++ b/src/test/java/com/google/devtools/build/lib/profiler/ProfilerTest.java
@@ -15,7 +15,6 @@
import static com.google.common.truth.Truth.assertThat;
import static java.nio.charset.StandardCharsets.ISO_8859_1;
-import static org.junit.Assert.fail;
import com.google.common.collect.ImmutableList;
import com.google.common.io.ByteStreams;
@@ -85,9 +84,9 @@
Path cacheFile = cacheDir.getRelative("profile1.dat");
profiler.start(ProfiledTaskKinds.ALL, cacheFile.getOutputStream(), "basic test", false,
BlazeClock.instance(), BlazeClock.instance().nanoTime());
- profiler.startTask(ProfilerTask.ACTION, "action task");
- profiler.logEvent(ProfilerTask.INFO, "event");
- profiler.completeTask(ProfilerTask.ACTION);
+ try (SilentCloseable c = profiler.profile(ProfilerTask.ACTION, "action task")) {
+ profiler.logEvent(ProfilerTask.INFO, "event");
+ }
profiler.stop();
ProfileInfo info = ProfileInfo.loadProfile(cacheFile);
info.calculateStats();
@@ -110,24 +109,21 @@
BlazeClock.instance(), BlazeClock.instance().nanoTime());
profiler.logSimpleTask(BlazeClock.instance().nanoTime(),
ProfilerTask.PHASE, "profiler start");
- profiler.startTask(ProfilerTask.ACTION, "complex task");
- profiler.logEvent(ProfilerTask.PHASE, "event1");
- profiler.startTask(ProfilerTask.ACTION_CHECK, "complex subtask");
- // next task takes less than 10 ms and should be only aggregated
- profiler.logSimpleTask(BlazeClock.instance().nanoTime(),
- ProfilerTask.VFS_STAT, "stat1");
- long startTime = BlazeClock.instance().nanoTime();
- clock.advanceMillis(20);
- // this one will take at least 20 ms and should be present
- profiler.logSimpleTask(startTime, ProfilerTask.VFS_STAT, "stat2");
- profiler.completeTask(ProfilerTask.ACTION_CHECK);
- profiler.completeTask(ProfilerTask.ACTION);
+ try (SilentCloseable c = profiler.profile(ProfilerTask.ACTION, "complex task")) {
+ profiler.logEvent(ProfilerTask.PHASE, "event1");
+ try (SilentCloseable c2 = profiler.profile(ProfilerTask.ACTION_CHECK, "complex subtask")) {
+ // next task takes less than 10 ms and should be only aggregated
+ profiler.logSimpleTask(BlazeClock.instance().nanoTime(),
+ ProfilerTask.VFS_STAT, "stat1");
+ long startTime = BlazeClock.instance().nanoTime();
+ clock.advanceMillis(20);
+ // this one will take at least 20 ms and should be present
+ profiler.logSimpleTask(startTime, ProfilerTask.VFS_STAT, "stat2");
+ }
+ }
profiler.stop();
// all other calls to profiler should be ignored
profiler.logEvent(ProfilerTask.PHASE, "should be ignored");
- // normally this would cause an exception but it is ignored since profiler
- // is disabled
- profiler.completeTask(ProfilerTask.ACTION_EXECUTE);
ProfileInfo info = ProfileInfo.loadProfile(cacheFile);
info.calculateStats();
@@ -167,11 +163,11 @@
Path cacheFile = cacheDir.getRelative("profile1.dat");
profiler.start(ProfiledTaskKinds.ALL, cacheFile.getOutputStream(), "basic test", true,
BlazeClock.instance(), BlazeClock.instance().nanoTime());
- profiler.startTask(ProfilerTask.ACTION, "action task");
- // Next task takes less than 10 ms but should be recorded anyway.
- clock.advanceMillis(1);
- profiler.logSimpleTask(BlazeClock.instance().nanoTime(), ProfilerTask.VFS_STAT, "stat1");
- profiler.completeTask(ProfilerTask.ACTION);
+ try (SilentCloseable c = profiler.profile(ProfilerTask.ACTION, "action task")) {
+ // Next task takes less than 10 ms but should be recorded anyway.
+ clock.advanceMillis(1);
+ profiler.logSimpleTask(BlazeClock.instance().nanoTime(), ProfilerTask.VFS_STAT, "stat1");
+ }
profiler.stop();
ProfileInfo info = ProfileInfo.loadProfile(cacheFile);
info.calculateStats();
@@ -300,22 +296,6 @@
}
@Test
- public void testInconsistentCompleteTask() throws Exception {
- Path cacheFile = cacheDir.getRelative("profile2.dat");
- profiler.start(ProfiledTaskKinds.ALL, cacheFile.getOutputStream(),
- "task stack inconsistency test", false,
- BlazeClock.instance(), BlazeClock.instance().nanoTime());
- profiler.startTask(ProfilerTask.PHASE, "some task");
- try {
- profiler.completeTask(ProfilerTask.ACTION);
- fail();
- } catch (IllegalStateException e) {
- // this is expected
- }
- profiler.stop();
- }
-
- @Test
public void testConcurrentProfiling() throws Exception {
Path cacheFile = cacheDir.getRelative("profile3.dat");
profiler.start(ProfiledTaskKinds.ALL, cacheFile.getOutputStream(), "concurrent test", false,
@@ -339,14 +319,14 @@
};
long id2 = thread2.getId();
- profiler.startTask(ProfilerTask.PHASE, "main task");
- profiler.logEvent(ProfilerTask.INFO, "starting threads");
- thread1.start();
- thread2.start();
- thread2.join();
- thread1.join();
- profiler.logEvent(ProfilerTask.INFO, "joined");
- profiler.completeTask(ProfilerTask.PHASE);
+ try (SilentCloseable c = profiler.profile(ProfilerTask.PHASE, "main task")) {
+ profiler.logEvent(ProfilerTask.INFO, "starting threads");
+ thread1.start();
+ thread2.start();
+ thread2.join();
+ thread1.join();
+ profiler.logEvent(ProfilerTask.INFO, "joined");
+ }
profiler.stop();
ProfileInfo info = ProfileInfo.loadProfile(cacheFile);
@@ -393,11 +373,11 @@
new Thread() {
@Override
public void run() {
- profiler.startTask(ProfilerTask.INFO, "complex task");
- for (int i = 0; i < 100; i++) {
- Profiler.instance().logEvent(ProfilerTask.INFO, "thread2a");
+ try (SilentCloseable c = profiler.profile(ProfilerTask.INFO, "complex task")) {
+ for (int i = 0; i < 100; i++) {
+ Profiler.instance().logEvent(ProfilerTask.INFO, "thread2a");
+ }
}
- profiler.completeTask(ProfilerTask.INFO);
try {
profiler.markPhase(ProfilePhase.EXECUTE);
} catch (InterruptedException e) {
@@ -441,10 +421,10 @@
profiler.start(ProfiledTaskKinds.ALL, cacheFile.getOutputStream(), "phase test", false,
BlazeClock.instance(), BlazeClock.instance().nanoTime());
for (int i = 0; i < 100; i++) {
- profiler.startTask(ProfilerTask.INFO, "outer task " + i);
- clock.advanceMillis(1);
- profiler.logEvent(ProfilerTask.INFO, "inner task " + i);
- profiler.completeTask(ProfilerTask.INFO);
+ try (SilentCloseable c = profiler.profile(ProfilerTask.INFO, "outer task " + i)) {
+ clock.advanceMillis(1);
+ profiler.logEvent(ProfilerTask.INFO, "inner task " + i);
+ }
}
profiler.stop();
@@ -470,12 +450,12 @@
Path dataFile = cacheDir.getRelative("profile5.dat");
profiler.start(ProfiledTaskKinds.ALL, dataFile.getOutputStream(), "phase test", false,
BlazeClock.instance(), BlazeClock.instance().nanoTime());
- profiler.startTask(ProfilerTask.INFO, "outer task");
- profiler.logEvent(ProfilerTask.PHASE, "inner task");
- profiler.completeTask(ProfilerTask.INFO);
- profiler.startTask(ProfilerTask.SCANNER, "outer task 2");
- profiler.logSimpleTask(Profiler.nanoTimeMaybe(), ProfilerTask.INFO, "inner task 2");
- profiler.completeTask(ProfilerTask.SCANNER);
+ try (SilentCloseable c = profiler.profile(ProfilerTask.INFO, "outer task")) {
+ profiler.logEvent(ProfilerTask.PHASE, "inner task");
+ }
+ try (SilentCloseable c = profiler.profile(ProfilerTask.SCANNER, "outer task 2")) {
+ profiler.logSimpleTask(Profiler.nanoTimeMaybe(), ProfilerTask.INFO, "inner task 2");
+ }
profiler.stop();
// Validate our test profile.
