diff --git a/src/main/java/com/google/devtools/build/lib/actions/CachingActionEvent.java b/src/main/java/com/google/devtools/build/lib/actions/CachingActionEvent.java new file mode 100644 index 00000000000000..343b4633dcebe4 --- /dev/null +++ b/src/main/java/com/google/devtools/build/lib/actions/CachingActionEvent.java @@ -0,0 +1,35 @@ +// Copyright 2021 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.actions; + +import static com.google.common.base.Preconditions.checkNotNull; + +import com.google.auto.value.AutoValue; +import com.google.devtools.build.lib.events.ExtendedEventHandler.ProgressLike; + +/** Notifies that an in-flight action is checking the cache. */ +@AutoValue +public abstract class CachingActionEvent implements ProgressLike { + + public static CachingActionEvent create(ActionExecutionMetadata action, String strategy) { + return new AutoValue_CachingActionEvent( + action, checkNotNull(strategy, "Strategy names are not optional")); + } + + /** Gets the metadata associated with the action. */ + public abstract ActionExecutionMetadata action(); + + /** Gets the name of the strategy on which the action is caching. */ + public abstract String strategy(); +} diff --git a/src/main/java/com/google/devtools/build/lib/exec/AbstractSpawnStrategy.java b/src/main/java/com/google/devtools/build/lib/exec/AbstractSpawnStrategy.java index 079c54a540aeb7..03ec3f14f3d3b3 100644 --- a/src/main/java/com/google/devtools/build/lib/exec/AbstractSpawnStrategy.java +++ b/src/main/java/com/google/devtools/build/lib/exec/AbstractSpawnStrategy.java @@ -28,9 +28,7 @@ import com.google.devtools.build.lib.actions.LostInputsActionExecutionException; import com.google.devtools.build.lib.actions.LostInputsExecException; import com.google.devtools.build.lib.actions.MetadataProvider; -import com.google.devtools.build.lib.actions.RunningActionEvent; import com.google.devtools.build.lib.actions.SandboxedSpawnStrategy; -import com.google.devtools.build.lib.actions.SchedulingActionEvent; import com.google.devtools.build.lib.actions.Spawn; import com.google.devtools.build.lib.actions.SpawnExecutedEvent; import com.google.devtools.build.lib.actions.SpawnResult; @@ -308,7 +306,7 @@ public SortedMap getInputMapping(PathFragment baseDir } @Override - public void report(ProgressStatus state, String name) { + public void report(ProgressStatus progress) { ActionExecutionMetadata action = spawn.getResourceOwner(); if (action.getOwner() == null) { return; @@ -322,17 +320,7 @@ public void report(ProgressStatus state, String name) { // TODO(ulfjack): We should report more details to the UI. ExtendedEventHandler eventHandler = actionExecutionContext.getEventHandler(); - switch (state) { - case EXECUTING: - case CHECKING_CACHE: - eventHandler.post(new RunningActionEvent(action, name)); - break; - case SCHEDULING: - eventHandler.post(new SchedulingActionEvent(action, name)); - break; - default: - break; - } + progress.postTo(eventHandler, action); } @Override diff --git a/src/main/java/com/google/devtools/build/lib/exec/BUILD b/src/main/java/com/google/devtools/build/lib/exec/BUILD index 471d6a879d7037..11606c087752de 100644 --- a/src/main/java/com/google/devtools/build/lib/exec/BUILD +++ b/src/main/java/com/google/devtools/build/lib/exec/BUILD @@ -264,14 +264,21 @@ java_library( java_library( name = "spawn_runner", - srcs = ["SpawnRunner.java"], + srcs = [ + "SpawnCheckingCacheEvent.java", + "SpawnExecutingEvent.java", + "SpawnRunner.java", + "SpawnSchedulingEvent.java", + ], deps = [ ":tree_deleter", "//src/main/java/com/google/devtools/build/lib/actions", "//src/main/java/com/google/devtools/build/lib/actions:artifacts", + "//src/main/java/com/google/devtools/build/lib/events", "//src/main/java/com/google/devtools/build/lib/util/io", "//src/main/java/com/google/devtools/build/lib/vfs", "//src/main/java/com/google/devtools/build/lib/vfs:pathfragment", + "//third_party:auto_value", "//third_party:jsr305", ], ) diff --git a/src/main/java/com/google/devtools/build/lib/exec/SpawnCheckingCacheEvent.java b/src/main/java/com/google/devtools/build/lib/exec/SpawnCheckingCacheEvent.java new file mode 100644 index 00000000000000..765408cdec1f80 --- /dev/null +++ b/src/main/java/com/google/devtools/build/lib/exec/SpawnCheckingCacheEvent.java @@ -0,0 +1,35 @@ +// Copyright 2021 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.exec; + +import com.google.auto.value.AutoValue; +import com.google.devtools.build.lib.actions.ActionExecutionMetadata; +import com.google.devtools.build.lib.actions.CachingActionEvent; +import com.google.devtools.build.lib.events.ExtendedEventHandler; +import com.google.devtools.build.lib.exec.SpawnRunner.ProgressStatus; + +/** Notifies that {@link SpawnRunner} is looking for a cache hit. */ +@AutoValue +public abstract class SpawnCheckingCacheEvent implements ProgressStatus { + public static SpawnCheckingCacheEvent create(String name) { + return new AutoValue_SpawnCheckingCacheEvent(name); + } + + public abstract String name(); + + @Override + public void postTo(ExtendedEventHandler eventHandler, ActionExecutionMetadata action) { + eventHandler.post(CachingActionEvent.create(action, name())); + } +} diff --git a/src/main/java/com/google/devtools/build/lib/exec/SpawnExecutingEvent.java b/src/main/java/com/google/devtools/build/lib/exec/SpawnExecutingEvent.java new file mode 100644 index 00000000000000..688b1433849adb --- /dev/null +++ b/src/main/java/com/google/devtools/build/lib/exec/SpawnExecutingEvent.java @@ -0,0 +1,42 @@ +// Copyright 2021 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.exec; + +import com.google.auto.value.AutoValue; +import com.google.devtools.build.lib.actions.ActionExecutionMetadata; +import com.google.devtools.build.lib.actions.RunningActionEvent; +import com.google.devtools.build.lib.events.ExtendedEventHandler; +import com.google.devtools.build.lib.exec.SpawnRunner.ProgressStatus; + +/** + * Notifies that {@link SpawnRunner} failed to find a cache hit and acquired the resources to + * execute. This MUST be posted before attempting to execute the subprocess. + * + *

Caching {@link SpawnRunner} implementations should only post this after a failed cache lookup, + * but may post this if cache lookup and execution happen within the same step, e.g. as part of a + * single RPC call with no mechanism to report cache misses. + */ +@AutoValue +public abstract class SpawnExecutingEvent implements ProgressStatus { + public static SpawnExecutingEvent create(String name) { + return new AutoValue_SpawnExecutingEvent(name); + } + + public abstract String name(); + + @Override + public void postTo(ExtendedEventHandler eventHandler, ActionExecutionMetadata action) { + eventHandler.post(new RunningActionEvent(action, name())); + } +} diff --git a/src/main/java/com/google/devtools/build/lib/exec/SpawnRunner.java b/src/main/java/com/google/devtools/build/lib/exec/SpawnRunner.java index 7b79837baeabdf..c19be841b224b2 100644 --- a/src/main/java/com/google/devtools/build/lib/exec/SpawnRunner.java +++ b/src/main/java/com/google/devtools/build/lib/exec/SpawnRunner.java @@ -14,6 +14,7 @@ package com.google.devtools.build.lib.exec; import com.google.devtools.build.lib.actions.ActionContext; +import com.google.devtools.build.lib.actions.ActionExecutionMetadata; import com.google.devtools.build.lib.actions.ActionInput; import com.google.devtools.build.lib.actions.Artifact.ArtifactExpander; import com.google.devtools.build.lib.actions.ArtifactPathResolver; @@ -24,6 +25,7 @@ import com.google.devtools.build.lib.actions.Spawn; import com.google.devtools.build.lib.actions.SpawnResult; import com.google.devtools.build.lib.actions.cache.MetadataInjector; +import com.google.devtools.build.lib.events.ExtendedEventHandler; import com.google.devtools.build.lib.util.io.FileOutErr; import com.google.devtools.build.lib.vfs.Path; import com.google.devtools.build.lib.vfs.PathFragment; @@ -103,25 +105,9 @@ public interface SpawnRunner { *

{@link SpawnRunner} implementations should post a progress status before any potentially * long-running operation. */ - enum ProgressStatus { - /** Spawn is waiting for local or remote resources to become available. */ - SCHEDULING, - - /** The {@link SpawnRunner} is looking for a cache hit. */ - CHECKING_CACHE, - - /** - * Resources are acquired, and there was probably no cache hit. This MUST be posted before - * attempting to execute the subprocess. - * - *

Caching {@link SpawnRunner} implementations should only post this after a failed cache - * lookup, but may post this if cache lookup and execution happen within the same step, e.g. as - * part of a single RPC call with no mechanism to report cache misses. - */ - EXECUTING, - - /** Downloading outputs from a remote machine. */ - DOWNLOADING + interface ProgressStatus { + /** Post this progress event to the given {@link ExtendedEventHandler}. */ + void postTo(ExtendedEventHandler eventHandler, ActionExecutionMetadata action); } /** @@ -213,7 +199,7 @@ SortedMap getInputMapping(PathFragment baseDirectory) throws IOException; /** Reports a progress update to the Spawn strategy. */ - void report(ProgressStatus state, String name); + void report(ProgressStatus progress); /** * Returns a {@link MetadataInjector} that allows a caller to inject metadata about spawn diff --git a/src/main/java/com/google/devtools/build/lib/exec/SpawnSchedulingEvent.java b/src/main/java/com/google/devtools/build/lib/exec/SpawnSchedulingEvent.java new file mode 100644 index 00000000000000..18825c6e8bd1b0 --- /dev/null +++ b/src/main/java/com/google/devtools/build/lib/exec/SpawnSchedulingEvent.java @@ -0,0 +1,37 @@ +// Copyright 2021 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.exec; + +import com.google.auto.value.AutoValue; +import com.google.devtools.build.lib.actions.ActionExecutionMetadata; +import com.google.devtools.build.lib.actions.SchedulingActionEvent; +import com.google.devtools.build.lib.events.ExtendedEventHandler; +import com.google.devtools.build.lib.exec.SpawnRunner.ProgressStatus; + +/** + * Notifies that {@link SpawnRunner} is waiting for local or remote resources to become available. + */ +@AutoValue +public abstract class SpawnSchedulingEvent implements ProgressStatus { + public static SpawnSchedulingEvent create(String name) { + return new AutoValue_SpawnSchedulingEvent(name); + } + + public abstract String name(); + + @Override + public void postTo(ExtendedEventHandler eventHandler, ActionExecutionMetadata action) { + eventHandler.post(new SchedulingActionEvent(action, name())); + } +} diff --git a/src/main/java/com/google/devtools/build/lib/exec/local/LocalSpawnRunner.java b/src/main/java/com/google/devtools/build/lib/exec/local/LocalSpawnRunner.java index 695b797102c814..746603c86a4df7 100644 --- a/src/main/java/com/google/devtools/build/lib/exec/local/LocalSpawnRunner.java +++ b/src/main/java/com/google/devtools/build/lib/exec/local/LocalSpawnRunner.java @@ -38,7 +38,9 @@ import com.google.devtools.build.lib.concurrent.ThreadSafety.ThreadSafe; import com.google.devtools.build.lib.exec.BinTools; import com.google.devtools.build.lib.exec.RunfilesTreeUpdater; +import com.google.devtools.build.lib.exec.SpawnExecutingEvent; import com.google.devtools.build.lib.exec.SpawnRunner; +import com.google.devtools.build.lib.exec.SpawnSchedulingEvent; import com.google.devtools.build.lib.profiler.Profiler; import com.google.devtools.build.lib.profiler.ProfilerTask; import com.google.devtools.build.lib.profiler.SilentCloseable; @@ -131,10 +133,10 @@ public SpawnResult exec(Spawn spawn, SpawnExecutionContext context) Profiler.instance() .profile(ProfilerTask.LOCAL_EXECUTION, spawn.getResourceOwner().getMnemonic())) { ActionExecutionMetadata owner = spawn.getResourceOwner(); - context.report(ProgressStatus.SCHEDULING, getName()); + context.report(SpawnSchedulingEvent.create(getName())); try (ResourceHandle handle = resourceManager.acquireResources(owner, spawn.getLocalResources())) { - context.report(ProgressStatus.EXECUTING, getName()); + context.report(SpawnExecutingEvent.create(getName())); if (!localExecutionOptions.localLockfreeOutput) { context.lockOutputFiles(); } diff --git a/src/main/java/com/google/devtools/build/lib/remote/RemoteSpawnCache.java b/src/main/java/com/google/devtools/build/lib/remote/RemoteSpawnCache.java index 235bc627a2dd24..27425c0e3d08e4 100644 --- a/src/main/java/com/google/devtools/build/lib/remote/RemoteSpawnCache.java +++ b/src/main/java/com/google/devtools/build/lib/remote/RemoteSpawnCache.java @@ -31,7 +31,8 @@ import com.google.devtools.build.lib.events.Event; import com.google.devtools.build.lib.events.Reporter; import com.google.devtools.build.lib.exec.SpawnCache; -import com.google.devtools.build.lib.exec.SpawnRunner.ProgressStatus; +import com.google.devtools.build.lib.exec.SpawnCheckingCacheEvent; +import com.google.devtools.build.lib.exec.SpawnExecutingEvent; import com.google.devtools.build.lib.exec.SpawnRunner.SpawnExecutionContext; import com.google.devtools.build.lib.profiler.Profiler; import com.google.devtools.build.lib.profiler.ProfilerTask; @@ -53,6 +54,12 @@ @ThreadSafe // If the RemoteActionCache implementation is thread-safe. final class RemoteSpawnCache implements SpawnCache { + private static final SpawnCheckingCacheEvent SPAWN_CHECKING_CACHE_EVENT = + SpawnCheckingCacheEvent.create("remote-cache"); + + private static final SpawnExecutingEvent SPAWN_EXECUTING_EVENT = + SpawnExecutingEvent.create("remote-cache"); + private final Path execRoot; private final RemoteOptions options; private final boolean verboseFailures; @@ -96,7 +103,7 @@ public CacheHandle lookup(Spawn spawn, SpawnExecutionContext context) Profiler prof = Profiler.instance(); if (options.remoteAcceptCached || (options.incompatibleRemoteResultsIgnoreDisk && useDiskCache(options))) { - context.report(ProgressStatus.CHECKING_CACHE, "remote-cache"); + context.report(SPAWN_CHECKING_CACHE_EVENT); // Metadata will be available in context.current() until we detach. // This is done via a thread-local variable. try { @@ -150,6 +157,8 @@ public CacheHandle lookup(Spawn spawn, SpawnExecutionContext context) } } + context.report(SPAWN_EXECUTING_EVENT); + context.prefetchInputs(); if (options.remoteUploadLocalResults diff --git a/src/main/java/com/google/devtools/build/lib/remote/RemoteSpawnRunner.java b/src/main/java/com/google/devtools/build/lib/remote/RemoteSpawnRunner.java index c34767e9817415..939c8786f10dec 100644 --- a/src/main/java/com/google/devtools/build/lib/remote/RemoteSpawnRunner.java +++ b/src/main/java/com/google/devtools/build/lib/remote/RemoteSpawnRunner.java @@ -44,7 +44,10 @@ import com.google.devtools.build.lib.exec.AbstractSpawnStrategy; import com.google.devtools.build.lib.exec.ExecutionOptions; import com.google.devtools.build.lib.exec.RemoteLocalFallbackRegistry; +import com.google.devtools.build.lib.exec.SpawnCheckingCacheEvent; +import com.google.devtools.build.lib.exec.SpawnExecutingEvent; import com.google.devtools.build.lib.exec.SpawnRunner; +import com.google.devtools.build.lib.exec.SpawnSchedulingEvent; import com.google.devtools.build.lib.profiler.Profiler; import com.google.devtools.build.lib.profiler.ProfilerTask; import com.google.devtools.build.lib.profiler.SilentCloseable; @@ -80,6 +83,15 @@ @ThreadSafe public class RemoteSpawnRunner implements SpawnRunner { + private static final SpawnCheckingCacheEvent SPAWN_CHECKING_CACHE_EVENT = + SpawnCheckingCacheEvent.create("remote"); + + private static final SpawnSchedulingEvent SPAWN_SCHEDULING_EVENT = + SpawnSchedulingEvent.create("remote"); + + private static final SpawnExecutingEvent SPAWN_EXECUTING_EVENT = + SpawnExecutingEvent.create("remote"); + private final Path execRoot; private final RemoteOptions remoteOptions; private final ExecutionOptions executionOptions; @@ -142,7 +154,7 @@ public void onNext(Operation o) throws IOException { } public void reportExecuting() { - context.report(ProgressStatus.EXECUTING, getName()); + context.report(SPAWN_EXECUTING_EVENT); reportedExecuting = true; } @@ -164,8 +176,6 @@ public SpawnResult exec(Spawn spawn, SpawnExecutionContext context) boolean uploadLocalResults = remoteOptions.remoteUploadLocalResults && spawnCacheableRemotely; boolean acceptCachedResult = remoteOptions.remoteAcceptCached && spawnCacheableRemotely; - context.report(ProgressStatus.SCHEDULING, getName()); - RemoteAction action = remoteExecutionService.buildRemoteAction(spawn, context); SpawnMetrics.Builder spawnMetrics = SpawnMetrics.Builder.forRemoteExec() @@ -178,6 +188,8 @@ public SpawnResult exec(Spawn spawn, SpawnExecutionContext context) Profiler prof = Profiler.instance(); try { + context.report(SPAWN_CHECKING_CACHE_EVENT); + // Try to lookup the action in the action cache. RemoteActionResult cachedResult; try (SilentCloseable c = prof.profile(ProfilerTask.REMOTE_CACHE_CHECK, "check cache hit")) { @@ -231,6 +243,8 @@ public SpawnResult exec(Spawn spawn, SpawnExecutionContext context) .minus(action.getNetworkTime().getDuration().minus(networkTimeStart))); } + context.report(SPAWN_SCHEDULING_EVENT); + ExecutingStatusReporter reporter = new ExecutingStatusReporter(context); RemoteActionResult result; try (SilentCloseable c = prof.profile(REMOTE_EXECUTION, "execute remotely")) { diff --git a/src/main/java/com/google/devtools/build/lib/runtime/UiEventHandler.java b/src/main/java/com/google/devtools/build/lib/runtime/UiEventHandler.java index 625670438f9927..f903cdff0be2d9 100644 --- a/src/main/java/com/google/devtools/build/lib/runtime/UiEventHandler.java +++ b/src/main/java/com/google/devtools/build/lib/runtime/UiEventHandler.java @@ -22,6 +22,7 @@ import com.google.devtools.build.lib.actions.ActionCompletionEvent; import com.google.devtools.build.lib.actions.ActionScanningCompletedEvent; import com.google.devtools.build.lib.actions.ActionStartedEvent; +import com.google.devtools.build.lib.actions.CachingActionEvent; import com.google.devtools.build.lib.actions.RunningActionEvent; import com.google.devtools.build.lib.actions.ScanningActionEvent; import com.google.devtools.build.lib.actions.SchedulingActionEvent; @@ -678,6 +679,13 @@ public void stopScanningAction(StoppedScanningActionEvent event) { refresh(); } + @Subscribe + @AllowConcurrentEvents + public void checkingActionCache(CachingActionEvent event) { + stateTracker.cachingAction(event); + refresh(); + } + @Subscribe @AllowConcurrentEvents public void schedulingAction(SchedulingActionEvent event) { diff --git a/src/main/java/com/google/devtools/build/lib/runtime/UiStateTracker.java b/src/main/java/com/google/devtools/build/lib/runtime/UiStateTracker.java index 11ac834e3b5368..4fa69856d9bac8 100644 --- a/src/main/java/com/google/devtools/build/lib/runtime/UiStateTracker.java +++ b/src/main/java/com/google/devtools/build/lib/runtime/UiStateTracker.java @@ -28,6 +28,7 @@ import com.google.devtools.build.lib.actions.ActionScanningCompletedEvent; import com.google.devtools.build.lib.actions.ActionStartedEvent; import com.google.devtools.build.lib.actions.Artifact; +import com.google.devtools.build.lib.actions.CachingActionEvent; import com.google.devtools.build.lib.actions.RunningActionEvent; import com.google.devtools.build.lib.actions.ScanningActionEvent; import com.google.devtools.build.lib.actions.SchedulingActionEvent; @@ -193,6 +194,13 @@ private static final class ActionState { */ boolean scanning; + /** + * Bitmap of strategies that are checking the cache of this action. + * + *

If non-zero, implies that {@link #scanning} is false. + */ + int cachingStrategiesBitmap = 0; + /** * Bitmap of strategies that are scheduling this action. * @@ -227,7 +235,9 @@ synchronized int countActions() { * scheduled or running. */ synchronized void setScanning(long nanoChangeTime) { - if (schedulingStrategiesBitmap == 0 && runningStrategiesBitmap == 0) { + if (cachingStrategiesBitmap == 0 + && schedulingStrategiesBitmap == 0 + && runningStrategiesBitmap == 0) { scanning = true; nanoStartTime = nanoChangeTime; } @@ -240,12 +250,29 @@ synchronized void setScanning(long nanoChangeTime) { * scheduled or running. */ synchronized void setStopScanning(long nanoChangeTime) { - if (schedulingStrategiesBitmap == 0 && runningStrategiesBitmap == 0) { + if (cachingStrategiesBitmap == 0 + && schedulingStrategiesBitmap == 0 + && runningStrategiesBitmap == 0) { scanning = false; nanoStartTime = nanoChangeTime; } } + /** + * Marks the action as caching with the given strategy. + * + *

Because we may receive events out of order, this does nothing if the action is already + * scheduled or running with this strategy. + */ + synchronized void setCaching(String strategy, long nanoChangeTime) { + int id = strategyIds.getId(strategy); + if ((schedulingStrategiesBitmap & id) == 0 && (runningStrategiesBitmap & id) == 0) { + scanning = false; + cachingStrategiesBitmap |= id; + nanoStartTime = nanoChangeTime; + } + } + /** * Marks the action as scheduling with the given strategy. * @@ -256,6 +283,7 @@ synchronized void setScheduling(String strategy, long nanoChangeTime) { int id = strategyIds.getId(strategy); if ((runningStrategiesBitmap & id) == 0) { scanning = false; + cachingStrategiesBitmap &= ~id; schedulingStrategiesBitmap |= id; nanoStartTime = nanoChangeTime; } @@ -270,6 +298,7 @@ synchronized void setScheduling(String strategy, long nanoChangeTime) { synchronized void setRunning(String strategy, long nanoChangeTime) { scanning = false; int id = strategyIds.getId(strategy); + cachingStrategiesBitmap &= ~id; schedulingStrategiesBitmap &= ~id; runningStrategiesBitmap |= id; nanoStartTime = nanoChangeTime; @@ -281,6 +310,8 @@ synchronized String describe() { return "Running"; } else if (schedulingStrategiesBitmap != 0) { return "Scheduling"; + } else if (cachingStrategiesBitmap != 0) { + return "Caching"; } else if (scanning) { return "Scanning"; } else { @@ -487,6 +518,13 @@ void stopScanningAction(StoppedScanningActionEvent event) { getActionState(action, actionId, now).setStopScanning(now); } + void cachingAction(CachingActionEvent event) { + ActionExecutionMetadata action = event.action(); + Artifact actionId = action.getPrimaryOutput(); + long now = clock.nanoTime(); + getActionState(action, actionId, now).setCaching(event.strategy(), now); + } + void schedulingAction(SchedulingActionEvent event) { ActionExecutionMetadata action = event.getActionMetadata(); Artifact actionId = event.getActionMetadata().getPrimaryOutput(); @@ -656,6 +694,8 @@ private String describeAction( String strategy = null; if (actionState.runningStrategiesBitmap != 0) { strategy = strategyIds.formatNames(actionState.runningStrategiesBitmap); + } else if (actionState.cachingStrategiesBitmap != 0) { + strategy = strategyIds.formatNames(actionState.cachingStrategiesBitmap); } else { String status = actionState.describe(); if (status == null) { diff --git a/src/main/java/com/google/devtools/build/lib/sandbox/AbstractSandboxSpawnRunner.java b/src/main/java/com/google/devtools/build/lib/sandbox/AbstractSandboxSpawnRunner.java index 0d062a0f54cdd8..e90981463e3eb4 100644 --- a/src/main/java/com/google/devtools/build/lib/sandbox/AbstractSandboxSpawnRunner.java +++ b/src/main/java/com/google/devtools/build/lib/sandbox/AbstractSandboxSpawnRunner.java @@ -30,7 +30,9 @@ import com.google.devtools.build.lib.actions.UserExecException; import com.google.devtools.build.lib.exec.BinTools; import com.google.devtools.build.lib.exec.ExecutionOptions; +import com.google.devtools.build.lib.exec.SpawnExecutingEvent; import com.google.devtools.build.lib.exec.SpawnRunner; +import com.google.devtools.build.lib.exec.SpawnSchedulingEvent; import com.google.devtools.build.lib.exec.TreeDeleter; import com.google.devtools.build.lib.profiler.Profiler; import com.google.devtools.build.lib.profiler.SilentCloseable; @@ -80,10 +82,10 @@ public AbstractSandboxSpawnRunner(CommandEnvironment cmdEnv) { public final SpawnResult exec(Spawn spawn, SpawnExecutionContext context) throws ExecException, InterruptedException { ActionExecutionMetadata owner = spawn.getResourceOwner(); - context.report(ProgressStatus.SCHEDULING, getName()); + context.report(SpawnSchedulingEvent.create(getName())); try (ResourceHandle ignored = resourceManager.acquireResources(owner, spawn.getLocalResources())) { - context.report(ProgressStatus.EXECUTING, getName()); + context.report(SpawnExecutingEvent.create(getName())); SandboxedSpawn sandbox = prepareSpawn(spawn, context); return runSpawn(spawn, sandbox, context); } catch (IOException e) { diff --git a/src/main/java/com/google/devtools/build/lib/worker/WorkerSpawnRunner.java b/src/main/java/com/google/devtools/build/lib/worker/WorkerSpawnRunner.java index ca6a3b0d497ae2..c280f73ee4417b 100644 --- a/src/main/java/com/google/devtools/build/lib/worker/WorkerSpawnRunner.java +++ b/src/main/java/com/google/devtools/build/lib/worker/WorkerSpawnRunner.java @@ -41,7 +41,9 @@ import com.google.devtools.build.lib.events.ExtendedEventHandler; import com.google.devtools.build.lib.exec.BinTools; import com.google.devtools.build.lib.exec.RunfilesTreeUpdater; +import com.google.devtools.build.lib.exec.SpawnExecutingEvent; import com.google.devtools.build.lib.exec.SpawnRunner; +import com.google.devtools.build.lib.exec.SpawnSchedulingEvent; import com.google.devtools.build.lib.exec.local.LocalEnvProvider; import com.google.devtools.build.lib.sandbox.SandboxHelpers; import com.google.devtools.build.lib.sandbox.SandboxHelpers.SandboxInputs; @@ -141,9 +143,9 @@ public boolean handlesCaching() { public SpawnResult exec(Spawn spawn, SpawnExecutionContext context) throws ExecException, IOException, InterruptedException { context.report( - ProgressStatus.SCHEDULING, - WorkerKey.makeWorkerTypeName( - Spawns.supportsMultiplexWorkers(spawn), context.speculating())); + SpawnSchedulingEvent.create( + WorkerKey.makeWorkerTypeName( + Spawns.supportsMultiplexWorkers(spawn), context.speculating()))); if (spawn.getToolFiles().isEmpty()) { throw createUserExecException( String.format(ERROR_MESSAGE_PREFIX + REASON_NO_TOOLS, spawn.getMnemonic()), @@ -419,7 +421,7 @@ WorkResponse execInWorker( // We acquired a worker and resources -- mark that as queuing time. spawnMetrics.setQueueTime(queueStopwatch.elapsed()); - context.report(ProgressStatus.EXECUTING, key.getWorkerTypeName()); + context.report(SpawnExecutingEvent.create(key.getWorkerTypeName())); try { // We consider `prepareExecution` to be also part of setup. Stopwatch prepareExecutionStopwatch = Stopwatch.createStarted(); diff --git a/src/test/java/com/google/devtools/build/lib/exec/local/LocalSpawnRunnerTest.java b/src/test/java/com/google/devtools/build/lib/exec/local/LocalSpawnRunnerTest.java index e0324700b44e9f..ad7256d80ca35a 100644 --- a/src/test/java/com/google/devtools/build/lib/exec/local/LocalSpawnRunnerTest.java +++ b/src/test/java/com/google/devtools/build/lib/exec/local/LocalSpawnRunnerTest.java @@ -44,8 +44,10 @@ import com.google.devtools.build.lib.actions.cache.MetadataInjector; import com.google.devtools.build.lib.exec.BinTools; import com.google.devtools.build.lib.exec.RunfilesTreeUpdater; +import com.google.devtools.build.lib.exec.SpawnExecutingEvent; import com.google.devtools.build.lib.exec.SpawnRunner.ProgressStatus; import com.google.devtools.build.lib.exec.SpawnRunner.SpawnExecutionContext; +import com.google.devtools.build.lib.exec.SpawnSchedulingEvent; import com.google.devtools.build.lib.exec.util.SpawnBuilder; import com.google.devtools.build.lib.runtime.ProcessWrapper; import com.google.devtools.build.lib.shell.JavaSubprocessFactory; @@ -264,8 +266,8 @@ public SortedMap getInputMapping(PathFragment baseDir } @Override - public void report(ProgressStatus state, String name) { - reportedStatus.add(state); + public void report(ProgressStatus progress) { + reportedStatus.add(progress); } @Override @@ -382,7 +384,8 @@ public void vanillaZeroExit() throws Exception { assertThat(policy.lockOutputFilesCalled).isTrue(); assertThat(policy.reportedStatus) - .containsExactly(ProgressStatus.SCHEDULING, ProgressStatus.EXECUTING).inOrder(); + .containsExactly(SpawnSchedulingEvent.create("local"), SpawnExecutingEvent.create("local")) + .inOrder(); } @Test diff --git a/src/test/java/com/google/devtools/build/lib/remote/RemoteSpawnCacheTest.java b/src/test/java/com/google/devtools/build/lib/remote/RemoteSpawnCacheTest.java index 69b54bde4811e0..4c273f6d1ee937 100644 --- a/src/test/java/com/google/devtools/build/lib/remote/RemoteSpawnCacheTest.java +++ b/src/test/java/com/google/devtools/build/lib/remote/RemoteSpawnCacheTest.java @@ -53,6 +53,8 @@ import com.google.devtools.build.lib.events.Reporter; import com.google.devtools.build.lib.events.StoredEventHandler; import com.google.devtools.build.lib.exec.SpawnCache.CacheHandle; +import com.google.devtools.build.lib.exec.SpawnCheckingCacheEvent; +import com.google.devtools.build.lib.exec.SpawnExecutingEvent; import com.google.devtools.build.lib.exec.SpawnInputExpander; import com.google.devtools.build.lib.exec.SpawnRunner.ProgressStatus; import com.google.devtools.build.lib.exec.SpawnRunner.SpawnExecutionContext; @@ -67,7 +69,6 @@ import com.google.devtools.build.lib.server.FailureDetails; import com.google.devtools.build.lib.server.FailureDetails.FailureDetail; import com.google.devtools.build.lib.server.FailureDetails.Spawn.Code; -import com.google.devtools.build.lib.util.Pair; import com.google.devtools.build.lib.util.io.FileOutErr; import com.google.devtools.build.lib.vfs.DigestHashFunction; import com.google.devtools.build.lib.vfs.FileSystem; @@ -110,7 +111,7 @@ public class RemoteSpawnCacheTest { @Mock private RemoteCache remoteCache; private RemoteSpawnCache cache; private FileOutErr outErr; - private final List> progressUpdates = new ArrayList<>(); + private final List progressUpdates = new ArrayList<>(); private StoredEventHandler eventHandler = new StoredEventHandler(); @@ -164,8 +165,8 @@ public SortedMap getInputMapping(PathFragment baseDir } @Override - public void report(ProgressStatus state, String name) { - progressUpdates.add(Pair.of(state, name)); + public void report(ProgressStatus progress) { + progressUpdates.add(progress); } @Override @@ -294,8 +295,7 @@ public Void answer(InvocationOnMock invocation) { // We expect the CachedLocalSpawnRunner to _not_ write to outErr at all. assertThat(outErr.hasRecordedOutput()).isFalse(); assertThat(outErr.hasRecordedStderr()).isFalse(); - assertThat(progressUpdates) - .containsExactly(Pair.of(ProgressStatus.CHECKING_CACHE, "remote-cache")); + assertThat(progressUpdates).containsExactly(SpawnCheckingCacheEvent.create("remote-cache")); } @Test @@ -340,7 +340,9 @@ public Void answer(InvocationOnMock invocation) { eq(outputFiles), eq(outErr)); assertThat(progressUpdates) - .containsExactly(Pair.of(ProgressStatus.CHECKING_CACHE, "remote-cache")); + .containsExactly( + SpawnCheckingCacheEvent.create("remote-cache"), + SpawnExecutingEvent.create("remote-cache")); } @Test @@ -508,7 +510,9 @@ public void failedActionsAreNotUploaded() throws Exception { eq(outputFiles), eq(outErr)); assertThat(progressUpdates) - .containsExactly(Pair.of(ProgressStatus.CHECKING_CACHE, "remote-cache")); + .containsExactly( + SpawnCheckingCacheEvent.create("remote-cache"), + SpawnExecutingEvent.create("remote-cache")); } @Test @@ -550,7 +554,9 @@ public void printWarningIfUploadFails() throws Exception { assertThat(evt.getKind()).isEqualTo(EventKind.WARNING); assertThat(evt.getMessage()).contains("cache down"); assertThat(progressUpdates) - .containsExactly(Pair.of(ProgressStatus.CHECKING_CACHE, "remote-cache")); + .containsExactly( + SpawnCheckingCacheEvent.create("remote-cache"), + SpawnExecutingEvent.create("remote-cache")); } @Test @@ -608,7 +614,9 @@ public Void answer(InvocationOnMock invocation) { assertThat(evt.getKind()).isEqualTo(EventKind.WARNING); assertThat(evt.getMessage()).contains("UNAVAILABLE"); assertThat(progressUpdates) - .containsExactly(Pair.of(ProgressStatus.CHECKING_CACHE, "remote-cache")); + .containsExactly( + SpawnCheckingCacheEvent.create("remote-cache"), + SpawnExecutingEvent.create("remote-cache")); } @Test @@ -678,7 +686,9 @@ public Void answer(InvocationOnMock invocation) { eq(outputFiles), eq(outErr)); assertThat(progressUpdates) - .containsExactly(Pair.of(ProgressStatus.CHECKING_CACHE, "remote-cache")); + .containsExactly( + SpawnCheckingCacheEvent.create("remote-cache"), + SpawnExecutingEvent.create("remote-cache")); assertThat(eventHandler.getEvents()).isEmpty(); // no warning is printed. } diff --git a/src/test/java/com/google/devtools/build/lib/remote/RemoteSpawnRunnerTest.java b/src/test/java/com/google/devtools/build/lib/remote/RemoteSpawnRunnerTest.java index 722f31ce15a90c..1518a30fa911b6 100644 --- a/src/test/java/com/google/devtools/build/lib/remote/RemoteSpawnRunnerTest.java +++ b/src/test/java/com/google/devtools/build/lib/remote/RemoteSpawnRunnerTest.java @@ -72,9 +72,11 @@ import com.google.devtools.build.lib.exec.AbstractSpawnStrategy; import com.google.devtools.build.lib.exec.ExecutionOptions; import com.google.devtools.build.lib.exec.RemoteLocalFallbackRegistry; +import com.google.devtools.build.lib.exec.SpawnCheckingCacheEvent; +import com.google.devtools.build.lib.exec.SpawnExecutingEvent; import com.google.devtools.build.lib.exec.SpawnRunner; -import com.google.devtools.build.lib.exec.SpawnRunner.ProgressStatus; import com.google.devtools.build.lib.exec.SpawnRunner.SpawnExecutionContext; +import com.google.devtools.build.lib.exec.SpawnSchedulingEvent; import com.google.devtools.build.lib.exec.util.FakeOwner; import com.google.devtools.build.lib.remote.common.CacheNotFoundException; import com.google.devtools.build.lib.remote.common.OperationObserver; @@ -1355,6 +1357,46 @@ public void accountingAddsDurationsForStages() { assertThat(spawnMetrics.processOutputsTime()).isEqualTo(Duration.ofSeconds(1)); } + @Test + public void shouldReportCheckingCacheBeforeScheduling() throws Exception { + // Arrange + RemoteSpawnRunner runner = newSpawnRunner(); + ExecuteResponse succeeded = + ExecuteResponse.newBuilder() + .setResult(ActionResult.newBuilder().setExitCode(0).build()) + .build(); + + Spawn spawn = newSimpleSpawn(); + SpawnExecutionContext policy = mock(SpawnExecutionContext.class); + when(policy.getTimeout()).thenReturn(Duration.ZERO); + + when(executor.executeRemotely( + any(RemoteActionExecutionContext.class), + any(ExecuteRequest.class), + any(OperationObserver.class))) + .thenAnswer( + invocationOnMock -> { + OperationObserver receiver = invocationOnMock.getArgument(2); + receiver.onNext(Operation.getDefaultInstance()); + return succeeded; + }); + + // Act + SpawnResult res = runner.exec(spawn, policy); + assertThat(res.status()).isEqualTo(Status.SUCCESS); + + // Assert + verify(executor) + .executeRemotely( + any(RemoteActionExecutionContext.class), + any(ExecuteRequest.class), + any(OperationObserver.class)); + InOrder reportOrder = inOrder(policy); + reportOrder.verify(policy, times(1)).report(SpawnCheckingCacheEvent.create("remote")); + reportOrder.verify(policy, times(1)).report(SpawnSchedulingEvent.create("remote")); + reportOrder.verify(policy, times(1)).report(SpawnExecutingEvent.create("remote")); + } + @Test public void shouldReportExecutingStatusWithoutMetadata() throws Exception { RemoteSpawnRunner runner = newSpawnRunner(); @@ -1374,7 +1416,7 @@ public void shouldReportExecutingStatusWithoutMetadata() throws Exception { .thenAnswer( invocationOnMock -> { OperationObserver receiver = invocationOnMock.getArgument(2); - verify(policy, never()).report(eq(ProgressStatus.EXECUTING), any(String.class)); + verify(policy, never()).report(SpawnExecutingEvent.create("remote")); receiver.onNext(Operation.getDefaultInstance()); return succeeded; }); @@ -1388,8 +1430,8 @@ public void shouldReportExecutingStatusWithoutMetadata() throws Exception { any(ExecuteRequest.class), any(OperationObserver.class)); InOrder reportOrder = inOrder(policy); - reportOrder.verify(policy, times(1)).report(eq(ProgressStatus.SCHEDULING), any(String.class)); - reportOrder.verify(policy, times(1)).report(eq(ProgressStatus.EXECUTING), any(String.class)); + reportOrder.verify(policy, times(1)).report(SpawnSchedulingEvent.create("remote")); + reportOrder.verify(policy, times(1)).report(SpawnExecutingEvent.create("remote")); } @Test @@ -1418,7 +1460,7 @@ public void shouldReportExecutingStatusAfterGotExecutingStageFromMetadata() thro ExecuteOperationMetadata.newBuilder().setStage(Value.QUEUED).build())) .build(); receiver.onNext(queued); - verify(policy, never()).report(eq(ProgressStatus.EXECUTING), any(String.class)); + verify(policy, never()).report(SpawnExecutingEvent.create("remote")); Operation executing = Operation.newBuilder() @@ -1442,8 +1484,8 @@ public void shouldReportExecutingStatusAfterGotExecutingStageFromMetadata() thro any(ExecuteRequest.class), any(OperationObserver.class)); InOrder reportOrder = inOrder(policy); - reportOrder.verify(policy, times(1)).report(eq(ProgressStatus.SCHEDULING), any(String.class)); - reportOrder.verify(policy, times(1)).report(eq(ProgressStatus.EXECUTING), any(String.class)); + reportOrder.verify(policy, times(1)).report(SpawnSchedulingEvent.create("remote")); + reportOrder.verify(policy, times(1)).report(SpawnExecutingEvent.create("remote")); } @Test @@ -1484,8 +1526,8 @@ public void shouldIgnoreInvalidMetadata() throws Exception { any(ExecuteRequest.class), any(OperationObserver.class)); InOrder reportOrder = inOrder(policy); - reportOrder.verify(policy, times(1)).report(eq(ProgressStatus.SCHEDULING), any(String.class)); - reportOrder.verify(policy, times(1)).report(eq(ProgressStatus.EXECUTING), any(String.class)); + reportOrder.verify(policy, times(1)).report(SpawnSchedulingEvent.create("remote")); + reportOrder.verify(policy, times(1)).report(SpawnExecutingEvent.create("remote")); } @Test @@ -1528,8 +1570,8 @@ public void shouldReportExecutingStatusIfNoExecutingStatusFromMetadata() throws any(ExecuteRequest.class), any(OperationObserver.class)); InOrder reportOrder = inOrder(policy); - reportOrder.verify(policy, times(1)).report(eq(ProgressStatus.SCHEDULING), any(String.class)); - reportOrder.verify(policy, times(1)).report(eq(ProgressStatus.EXECUTING), any(String.class)); + reportOrder.verify(policy, times(1)).report(SpawnSchedulingEvent.create("remote")); + reportOrder.verify(policy, times(1)).report(SpawnExecutingEvent.create("remote")); } @Test @@ -1559,8 +1601,8 @@ public void shouldReportExecutingStatusEvenNoOperationFromServer() throws Except any(ExecuteRequest.class), any(OperationObserver.class)); InOrder reportOrder = inOrder(policy); - reportOrder.verify(policy, times(1)).report(eq(ProgressStatus.SCHEDULING), any(String.class)); - reportOrder.verify(policy, times(1)).report(eq(ProgressStatus.EXECUTING), any(String.class)); + reportOrder.verify(policy, times(1)).report(SpawnSchedulingEvent.create("remote")); + reportOrder.verify(policy, times(1)).report(SpawnExecutingEvent.create("remote")); } private static Spawn newSimpleSpawn(Artifact... outputs) { diff --git a/src/test/java/com/google/devtools/build/lib/remote/util/FakeSpawnExecutionContext.java b/src/test/java/com/google/devtools/build/lib/remote/util/FakeSpawnExecutionContext.java index 28d70a4dd6c7ab..9510273fb4cfa3 100644 --- a/src/test/java/com/google/devtools/build/lib/remote/util/FakeSpawnExecutionContext.java +++ b/src/test/java/com/google/devtools/build/lib/remote/util/FakeSpawnExecutionContext.java @@ -119,7 +119,7 @@ public SortedMap getInputMapping(PathFragment baseDir } @Override - public void report(ProgressStatus state, String name) { + public void report(ProgressStatus progress) { // Intentionally left empty. } diff --git a/src/test/java/com/google/devtools/build/lib/worker/WorkerSpawnRunnerTest.java b/src/test/java/com/google/devtools/build/lib/worker/WorkerSpawnRunnerTest.java index dbe71a4822ba0f..ce2ac4ea7134d7 100644 --- a/src/test/java/com/google/devtools/build/lib/worker/WorkerSpawnRunnerTest.java +++ b/src/test/java/com/google/devtools/build/lib/worker/WorkerSpawnRunnerTest.java @@ -36,7 +36,7 @@ import com.google.devtools.build.lib.collect.nestedset.NestedSetBuilder; import com.google.devtools.build.lib.collect.nestedset.Order; import com.google.devtools.build.lib.events.ExtendedEventHandler; -import com.google.devtools.build.lib.exec.SpawnRunner.ProgressStatus; +import com.google.devtools.build.lib.exec.SpawnExecutingEvent; import com.google.devtools.build.lib.exec.SpawnRunner.SpawnExecutionContext; import com.google.devtools.build.lib.exec.local.LocalEnvProvider; import com.google.devtools.build.lib.sandbox.SandboxHelpers; @@ -137,7 +137,7 @@ public void testExecInWorker_happyPath() throws ExecException, InterruptedExcept assertThat(response.getRequestId()).isEqualTo(0); assertThat(response.getOutput()).isEqualTo("out"); assertThat(logFile.exists()).isFalse(); - verify(context, times(1)).report(ProgressStatus.EXECUTING, "worker"); + verify(context, times(1)).report(SpawnExecutingEvent.create("worker")); } @Test @@ -172,7 +172,7 @@ public void testExecInWorker_finishesAsyncOnInterrupt() throws InterruptedExcept inputFileCache, spawnMetrics)); assertThat(logFile.exists()).isFalse(); - verify(context, times(1)).report(ProgressStatus.EXECUTING, "worker"); + verify(context, times(1)).report(SpawnExecutingEvent.create("worker")); verify(worker, times(1)).putRequest(WorkRequest.newBuilder().setRequestId(0).build()); } @@ -225,7 +225,7 @@ public void testExecInWorker_sendsCancelMessageOnInterrupt() spawnMetrics)); secondResponseRequested.acquire(); assertThat(logFile.exists()).isFalse(); - verify(context, times(1)).report(ProgressStatus.EXECUTING, "worker"); + verify(context, times(1)).report(SpawnExecutingEvent.create("worker")); ArgumentCaptor argumentCaptor = ArgumentCaptor.forClass(WorkRequest.class); verify(worker, times(2)).putRequest(argumentCaptor.capture()); assertThat(argumentCaptor.getAllValues().get(0)) @@ -273,7 +273,7 @@ public void testExecInWorker_unsandboxedDiesOnInterrupt() spawnMetrics)); assertThat(logFile.exists()).isFalse(); - verify(context, times(1)).report(ProgressStatus.EXECUTING, "worker"); + verify(context, times(1)).report(SpawnExecutingEvent.create("worker")); ArgumentCaptor argumentCaptor = ArgumentCaptor.forClass(WorkRequest.class); verify(worker, times(1)).putRequest(argumentCaptor.capture()); assertThat(argumentCaptor.getAllValues().get(0)) @@ -320,7 +320,7 @@ public void testExecInWorker_noMultiplexWithDynamic() assertThat(response.getRequestId()).isEqualTo(0); assertThat(response.getOutput()).isEqualTo("out"); assertThat(logFile.exists()).isFalse(); - verify(context, times(1)).report(ProgressStatus.EXECUTING, "worker"); + verify(context, times(1)).report(SpawnExecutingEvent.create("worker")); } private void assertRecordedResponsethrowsException(String recordedResponse, String exceptionText)