Track the time spent in source and output-tree diff checking.
PiperOrigin-RevId: 233971847
diff --git a/src/main/java/com/google/devtools/build/lib/buildtool/ExecutionFinishedEvent.java b/src/main/java/com/google/devtools/build/lib/buildtool/ExecutionFinishedEvent.java
deleted file mode 100644
index 33c1baa..0000000
--- a/src/main/java/com/google/devtools/build/lib/buildtool/ExecutionFinishedEvent.java
+++ /dev/null
@@ -1,63 +0,0 @@
-// Copyright 2014 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.buildtool;
-
-import com.google.common.collect.ImmutableMap;
-
-import java.util.HashMap;
-import java.util.Map;
-
-/**
- * Event signaling the end of the execution phase. Contains statistics about the action cache,
- * the metadata cache and about last file save times.
- */
-public class ExecutionFinishedEvent {
-
- private final int outputDirtyFiles;
- private final int outputModifiedFilesDuringPreviousBuild;
- /** The mtime of the most recently saved source file when the build starts. */
- private long lastFileSaveTimeInMillis;
-
- /**
- * The (filename, mtime) pairs of all files saved between the last build's
- * start time and the current build's start time. Only applies to builds
- * running with existing Blaze servers. Currently disabled.
- */
- private Map<String, Long> changedFileSaveTimes = new HashMap<>();
-
- public ExecutionFinishedEvent(Map<String, Long> changedFileSaveTimes,
- long lastFileSaveTimeInMillis, int outputDirtyFiles,
- int outputModifiedFilesDuringPreviousBuild) {
- this.outputDirtyFiles = outputDirtyFiles;
- this.outputModifiedFilesDuringPreviousBuild = outputModifiedFilesDuringPreviousBuild;
- this.changedFileSaveTimes = ImmutableMap.copyOf(changedFileSaveTimes);
- this.lastFileSaveTimeInMillis = lastFileSaveTimeInMillis;
- }
-
- public long getLastFileSaveTimeInMillis() {
- return lastFileSaveTimeInMillis;
- }
-
- public int getOutputDirtyFiles() {
- return outputDirtyFiles;
- }
-
- public int getOutputModifiedFilesDuringPreviousBuild() {
- return outputModifiedFilesDuringPreviousBuild;
- }
-
- public Map<String, Long> getChangedFileSaveTimes() {
- return changedFileSaveTimes;
- }
-}
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 2445087..40b8887 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
@@ -368,13 +368,7 @@
// Handlers process these events and others (e.g. CommandCompleteEvent), even in the event of
// a catastrophic failure. Posting these is consistent with other behavior.
- env.getEventBus()
- .post(
- new ExecutionFinishedEvent(
- ImmutableMap.of(),
- 0L,
- skyframeExecutor.getOutputDirtyFilesAndClear(),
- skyframeExecutor.getModifiedFilesDuringPreviousBuildAndClear()));
+ env.getEventBus().post(skyframeExecutor.createExecutionFinishedEvent());
env.getEventBus()
.post(new ExecutionPhaseCompleteEvent(timer.stop().elapsed(TimeUnit.MILLISECONDS)));
diff --git a/src/main/java/com/google/devtools/build/lib/buildtool/SkyframeBuilder.java b/src/main/java/com/google/devtools/build/lib/buildtool/SkyframeBuilder.java
index 7ae88b4..d77ef7f 100644
--- a/src/main/java/com/google/devtools/build/lib/buildtool/SkyframeBuilder.java
+++ b/src/main/java/com/google/devtools/build/lib/buildtool/SkyframeBuilder.java
@@ -107,9 +107,7 @@
@Nullable Range<Long> lastExecutionTimeRange,
TopLevelArtifactContext topLevelArtifactContext)
throws BuildFailedException, AbruptExitException, TestExecException, InterruptedException {
- try (SilentCloseable c = Profiler.instance().profile("detectModifiedOutputFiles")) {
- skyframeExecutor.detectModifiedOutputFiles(modifiedOutputFiles, lastExecutionTimeRange);
- }
+ skyframeExecutor.detectModifiedOutputFiles(modifiedOutputFiles, lastExecutionTimeRange);
try (SilentCloseable c = Profiler.instance().profile("configureActionExecutor")) {
skyframeExecutor.configureActionExecutor(fileCache, actionInputPrefetcher);
}
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 6c7a4d7..f906215 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
@@ -20,7 +20,6 @@
import com.google.devtools.build.lib.actions.ActionKeyContext;
import com.google.devtools.build.lib.actions.ActionResultReceivedEvent;
import com.google.devtools.build.lib.buildtool.BuildRequest;
-import com.google.devtools.build.lib.buildtool.ExecutionFinishedEvent;
import com.google.devtools.build.lib.buildtool.buildevent.BuildCompleteEvent;
import com.google.devtools.build.lib.buildtool.buildevent.ExecutionStartingEvent;
import com.google.devtools.build.lib.clock.BlazeClock;
@@ -31,6 +30,7 @@
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.ExecutionFinishedEvent;
import java.nio.charset.StandardCharsets;
import java.util.ArrayList;
import java.util.List;
diff --git a/src/main/java/com/google/devtools/build/lib/skyframe/ExecutionFinishedEvent.java b/src/main/java/com/google/devtools/build/lib/skyframe/ExecutionFinishedEvent.java
new file mode 100644
index 0000000..8db7f9e
--- /dev/null
+++ b/src/main/java/com/google/devtools/build/lib/skyframe/ExecutionFinishedEvent.java
@@ -0,0 +1,57 @@
+// Copyright 2014 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.skyframe;
+
+import java.time.Duration;
+
+/**
+ * Event signaling the end of the execution phase. Contains statistics about the action cache,
+ * the metadata cache and about last file save times.
+ */
+public class ExecutionFinishedEvent {
+ public static final ExecutionFinishedEvent EMPTY =
+ new ExecutionFinishedEvent(0, 0, Duration.ZERO, Duration.ZERO);
+
+ private final int outputDirtyFiles;
+ private final int outputModifiedFilesDuringPreviousBuild;
+ private final Duration sourceDiffCheckingDuration;
+ private final Duration outputTreeDiffCheckingDuration;
+
+ ExecutionFinishedEvent(
+ int outputDirtyFiles,
+ int outputModifiedFilesDuringPreviousBuild,
+ Duration sourceDiffCheckingDuration,
+ Duration outputTreeDiffCheckingDuration) {
+ this.outputDirtyFiles = outputDirtyFiles;
+ this.outputModifiedFilesDuringPreviousBuild = outputModifiedFilesDuringPreviousBuild;
+ this.sourceDiffCheckingDuration = sourceDiffCheckingDuration;
+ this.outputTreeDiffCheckingDuration = outputTreeDiffCheckingDuration;
+ }
+
+ public int getOutputDirtyFiles() {
+ return outputDirtyFiles;
+ }
+
+ public int getOutputModifiedFilesDuringPreviousBuild() {
+ return outputModifiedFilesDuringPreviousBuild;
+ }
+
+ public Duration getSourceDiffCheckingDuration() {
+ return sourceDiffCheckingDuration;
+ }
+
+ public Duration getOutputTreeDiffCheckingDuration() {
+ return outputTreeDiffCheckingDuration;
+ }
+}
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 2c97847..1c051f3 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
@@ -55,6 +55,7 @@
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.ProfilerTask;
import com.google.devtools.build.lib.profiler.SilentCloseable;
import com.google.devtools.build.lib.query2.AqueryActionFilter;
import com.google.devtools.build.lib.skyframe.AspectValue.AspectKey;
@@ -93,6 +94,7 @@
import com.google.devtools.build.skyframe.SkyValue;
import com.google.devtools.common.options.OptionsProvider;
import java.io.PrintStream;
+import java.time.Duration;
import java.util.ArrayList;
import java.util.Collection;
import java.util.EnumSet;
@@ -133,6 +135,12 @@
private final Iterable<SkyValueDirtinessChecker> customDirtinessCheckers;
private Set<String> previousClientEnvironment = ImmutableSet.of();
+ private int modifiedFiles;
+ private int outputDirtyFiles;
+ private int modifiedFilesDuringPreviousBuild;
+ private Duration sourceDiffCheckingDuration;
+ private Duration outputTreeDiffCheckingDuration;
+
private SequencedSkyframeExecutor(
Consumer<SkyframeExecutor> skyframeExecutorConsumerOnInit,
EvaluatorSupplier evaluatorSupplier,
@@ -309,9 +317,12 @@
clientEnv,
tsgm,
options);
- try (SilentCloseable c = Profiler.instance().profile("handleDiffs")) {
- handleDiffs(eventHandler, packageCacheOptions.checkOutputFiles, options);
- }
+ long startTime = System.nanoTime();
+ handleDiffs(eventHandler, packageCacheOptions.checkOutputFiles, options);
+ long stopTime = System.nanoTime();
+ Profiler.instance().logSimpleTask(startTime, stopTime, ProfilerTask.INFO, "handleDiffs");
+ long duration = stopTime - startTime;
+ sourceDiffCheckingDuration = duration > 0 ? Duration.ofNanos(duration) : Duration.ZERO;
}
/**
@@ -674,9 +685,8 @@
@Override
public void detectModifiedOutputFiles(
ModifiedFileSet modifiedOutputFiles, @Nullable Range<Long> lastExecutionTimeRange)
- throws AbruptExitException, InterruptedException {
-
- // Detect external modifications in the output tree.
+ throws InterruptedException {
+ long startTime = System.nanoTime();
FilesystemValueChecker fsvc =
new FilesystemValueChecker(Preconditions.checkNotNull(tsgm.get()), lastExecutionTimeRange);
BatchStat batchStatter = outputService == null ? null : outputService.getBatchStatter();
@@ -686,7 +696,12 @@
modifiedFiles += fsvc.getNumberOfModifiedOutputFiles();
outputDirtyFiles += fsvc.getNumberOfModifiedOutputFiles();
modifiedFilesDuringPreviousBuild += fsvc.getNumberOfModifiedOutputFilesDuringPreviousBuild();
- informAboutNumberOfModifiedFiles();
+ logger.info(String.format("Found %d modified files from last build", modifiedFiles));
+ long stopTime = System.nanoTime();
+ Profiler.instance()
+ .logSimpleTask(startTime, stopTime, ProfilerTask.INFO, "detectModifiedOutputFiles");
+ long duration = stopTime - startTime;
+ outputTreeDiffCheckingDuration = duration > 0 ? Duration.ofNanos(duration) : Duration.ZERO;
}
@Override
@@ -830,6 +845,21 @@
}
@Override
+ public ExecutionFinishedEvent createExecutionFinishedEvent() {
+ ExecutionFinishedEvent result =
+ new ExecutionFinishedEvent(
+ outputDirtyFiles,
+ modifiedFilesDuringPreviousBuild,
+ sourceDiffCheckingDuration,
+ outputTreeDiffCheckingDuration);
+ outputDirtyFiles = 0;
+ modifiedFilesDuringPreviousBuild = 0;
+ sourceDiffCheckingDuration = Duration.ZERO;
+ outputTreeDiffCheckingDuration = Duration.ZERO;
+ return result;
+ }
+
+ @Override
public void deleteOldNodes(long versionWindowForDirtyGc) {
// TODO(bazel-team): perhaps we should come up with a separate GC class dedicated to maintaining
// value garbage. If we ever do so, this logic should be moved there.
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 5593383..a94ea91 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
@@ -293,10 +293,6 @@
protected SkyframeProgressReceiver progressReceiver;
private final AtomicReference<CyclesReporter> cyclesReporter = new AtomicReference<>();
- protected int modifiedFiles;
- protected int outputDirtyFiles;
- protected int modifiedFilesDuringPreviousBuild;
-
@VisibleForTesting boolean lastAnalysisDiscarded = false;
private boolean analysisCacheDiscarded = false;
@@ -1171,16 +1167,6 @@
return new SkyFunctionEnvironmentForTesting(eventHandler, this);
}
- /**
- * Informs user about number of modified files (source and output files).
- */
- // Note, that number of modified files in some cases can be bigger than actual number of
- // modified files for targets in current request. Skyframe may check for modification all files
- // from previous requests.
- protected void informAboutNumberOfModifiedFiles() {
- logger.info(String.format("Found %d modified files from last build", modifiedFiles));
- }
-
public EventBus getEventBus() {
return eventBus.get();
}
@@ -2696,17 +2682,7 @@
}
}
- public int getOutputDirtyFilesAndClear() {
- int result = outputDirtyFiles;
- outputDirtyFiles = 0;
- return result;
- }
-
- public int getModifiedFilesDuringPreviousBuildAndClear() {
- int result = modifiedFilesDuringPreviousBuild;
- modifiedFilesDuringPreviousBuild = 0;
- return result;
- }
+ public abstract ExecutionFinishedEvent createExecutionFinishedEvent();
private <T extends SkyValue> EvaluationResult<T> evaluate(
Iterable<? extends SkyKey> roots,
