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..e976f3061e8591 --- /dev/null +++ b/src/main/java/com/google/devtools/build/lib/actions/CachingActionEvent.java @@ -0,0 +1,36 @@ +package com.google.devtools.build.lib.actions; + +import static com.google.common.base.Preconditions.checkNotNull; + +import com.google.devtools.build.lib.events.ExtendedEventHandler.ProgressLike; + +/** + * Notifies that an in-flight action is checking the cache. + */ +public class CachingActionEvent implements ProgressLike { + + private final ActionExecutionMetadata action; + private final String strategy; + + /** + * Constructs a new event. + */ + public CachingActionEvent(ActionExecutionMetadata action, String strategy) { + this.action = action; + this.strategy = checkNotNull(strategy, "Strategy names are not optional"); + } + + /** + * Gets the metadata associated with the action. + */ + public ActionExecutionMetadata getActionMetadata() { + return action; + } + + /** + * Gets the name of the strategy on which the action is caching. + */ + public String getStrategy() { + return strategy; + } +} \ No newline at end of file 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 0cfb2b77e6db01..390ca1e126fcf8 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 @@ -29,9 +29,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; @@ -318,7 +316,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; @@ -332,17 +330,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 268defdc80bac2..25ac115b44341d 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..595ce49f56989c --- /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; + +/** The {@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(new CachingActionEvent(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..99da418c7ba9bf --- /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; + +/** + * 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. + */ +@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 185cfcd4a088f5..5cadd596132db3 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; @@ -25,6 +26,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; @@ -104,25 +106,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); } /** @@ -214,7 +200,7 @@ SortedMap getInputMapping(PathFragment baseDirectory) throws IOException, ForbiddenActionInputException; /** 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..ff16bef57a0ef3 --- /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; + +/** + * Spawn 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 d63bca46d13334..81a6af8dc883c4 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,6 +38,8 @@ 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.SpawnSchedulingEvent; import com.google.devtools.build.lib.exec.SpawnRunner; import com.google.devtools.build.lib.profiler.Profiler; import com.google.devtools.build.lib.profiler.ProfilerTask; @@ -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 340210ba3a13db..bc2d2d1a8bf495 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 @@ -33,7 +33,7 @@ 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.SpawnRunner.SpawnExecutionContext; import com.google.devtools.build.lib.profiler.Profiler; import com.google.devtools.build.lib.profiler.ProfilerTask; @@ -96,7 +96,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(SpawnCheckingCacheEvent.create("remote-cache")); // Metadata will be available in context.current() until we detach. // This is done via a thread-local variable. try { 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 ea31f5dc3ee393..26f0295bdb8bdc 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 @@ -45,6 +45,9 @@ 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.SpawnSchedulingEvent; import com.google.devtools.build.lib.exec.SpawnRunner; import com.google.devtools.build.lib.profiler.Profiler; import com.google.devtools.build.lib.profiler.ProfilerTask; @@ -143,7 +146,7 @@ public void onNext(Operation o) throws IOException { } public void reportExecuting() { - context.report(ProgressStatus.EXECUTING, getName()); + context.report(SpawnExecutingEvent.create(getName())); reportedExecuting = true; } @@ -165,8 +168,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() @@ -179,6 +180,8 @@ public SpawnResult exec(Spawn spawn, SpawnExecutionContext context) Profiler prof = Profiler.instance(); try { + context.report(SpawnCheckingCacheEvent.create(getName())); + // Try to lookup the action in the action cache. RemoteActionResult cachedResult; try (SilentCloseable c = prof.profile(ProfilerTask.REMOTE_CACHE_CHECK, "check cache hit")) { @@ -232,6 +235,8 @@ public SpawnResult exec(Spawn spawn, SpawnExecutionContext context) .minus(action.getNetworkTime().getDuration().minus(networkTimeStart))); } + context.report(SpawnSchedulingEvent.create(getName())); + 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 215e60f0191e90..cb525751896d52 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; @@ -671,6 +672,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..f1dd9596213564 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,7 @@ 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,8 +248,23 @@ 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; } } @@ -256,6 +279,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 +294,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 +306,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 +514,13 @@ void stopScanningAction(StoppedScanningActionEvent event) { getActionState(action, actionId, now).setStopScanning(now); } + void cachingAction(CachingActionEvent event) { + ActionExecutionMetadata action = event.getActionMetadata(); + Artifact actionId = event.getActionMetadata().getPrimaryOutput(); + long now = clock.nanoTime(); + getActionState(action, actionId, now).setCaching(event.getStrategy(), now); + } + void schedulingAction(SchedulingActionEvent event) { ActionExecutionMetadata action = event.getActionMetadata(); Artifact actionId = event.getActionMetadata().getPrimaryOutput(); @@ -656,6 +690,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 f7e03f000328bd..1e28219ca8e226 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 @@ -31,6 +31,8 @@ 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.SpawnSchedulingEvent; import com.google.devtools.build.lib.exec.SpawnRunner; import com.google.devtools.build.lib.exec.TreeDeleter; import com.google.devtools.build.lib.profiler.Profiler; @@ -81,10 +83,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 7729b5d9ea5e15..45b04129946b8c 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 @@ -42,6 +42,8 @@ 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.SpawnSchedulingEvent; import com.google.devtools.build.lib.exec.SpawnRunner; import com.google.devtools.build.lib.exec.local.LocalEnvProvider; import com.google.devtools.build.lib.sandbox.SandboxHelpers; @@ -142,9 +144,8 @@ public boolean handlesCaching() { public SpawnResult exec(Spawn spawn, SpawnExecutionContext context) throws ExecException, IOException, InterruptedException, ForbiddenActionInputException { 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()), @@ -423,7 +424,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 8504d598a9607f..62cc8803e720a9 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 @@ -48,8 +48,10 @@ import com.google.devtools.build.lib.actions.util.ActionsTestUtil; 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; @@ -269,8 +271,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 @@ -387,7 +389,7 @@ 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 9935cfd8913b04..7308c2a8d16325 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 @@ -54,6 +54,7 @@ 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.SpawnInputExpander; import com.google.devtools.build.lib.exec.SpawnRunner.ProgressStatus; import com.google.devtools.build.lib.exec.SpawnRunner.SpawnExecutionContext; @@ -68,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; @@ -111,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(); @@ -165,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 @@ -296,7 +296,7 @@ public Void answer(InvocationOnMock invocation) { assertThat(outErr.hasRecordedOutput()).isFalse(); assertThat(outErr.hasRecordedStderr()).isFalse(); assertThat(progressUpdates) - .containsExactly(Pair.of(ProgressStatus.CHECKING_CACHE, "remote-cache")); + .containsExactly(SpawnCheckingCacheEvent.create("remote-cache")); } @Test @@ -341,7 +341,7 @@ public Void answer(InvocationOnMock invocation) { eq(outputFiles), eq(outErr)); assertThat(progressUpdates) - .containsExactly(Pair.of(ProgressStatus.CHECKING_CACHE, "remote-cache")); + .containsExactly(SpawnCheckingCacheEvent.create("remote-cache")); } @Test @@ -509,7 +509,7 @@ public void failedActionsAreNotUploaded() throws Exception { eq(outputFiles), eq(outErr)); assertThat(progressUpdates) - .containsExactly(Pair.of(ProgressStatus.CHECKING_CACHE, "remote-cache")); + .containsExactly(SpawnCheckingCacheEvent.create("remote-cache")); } @Test @@ -551,7 +551,7 @@ 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")); } @Test @@ -609,7 +609,7 @@ 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")); } @Test @@ -679,7 +679,7 @@ public Void answer(InvocationOnMock invocation) { eq(outputFiles), eq(outErr)); assertThat(progressUpdates) - .containsExactly(Pair.of(ProgressStatus.CHECKING_CACHE, "remote-cache")); + .containsExactly(SpawnCheckingCacheEvent.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 37bb35d731956e..8f847aa9d2b19b 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 @@ -73,9 +73,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; @@ -1356,6 +1358,43 @@ public void accountingAddsDurationsForStages() { assertThat(spawnMetrics.processOutputsTime()).isEqualTo(Duration.ofSeconds(1)); } + @Test + public void shouldReportCheckingCacheBeforeScheduling() throws Exception { + 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; + }); + + SpawnResult res = runner.exec(spawn, policy); + assertThat(res.status()).isEqualTo(Status.SUCCESS); + + 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(); @@ -1375,7 +1414,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; }); @@ -1389,8 +1428,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 @@ -1419,7 +1458,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() @@ -1443,8 +1482,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 @@ -1485,8 +1524,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 @@ -1529,8 +1568,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 @@ -1560,8 +1599,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 d7cbf993ac6abb..4eb847c5436aac 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 @@ -120,7 +120,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)