Add ExecutionGraphDumpModule This module writes a file containing a graph of all executed spawns and performance metrics. PiperOrigin-RevId: 475605631 Change-Id: I499a585c0767fa5f613eff77ab9404979cc217a8
diff --git a/src/main/java/com/google/devtools/build/lib/BUILD b/src/main/java/com/google/devtools/build/lib/BUILD index 7632337..69c820d 100644 --- a/src/main/java/com/google/devtools/build/lib/BUILD +++ b/src/main/java/com/google/devtools/build/lib/BUILD
@@ -415,6 +415,7 @@ "//src/main/protobuf:any_java_proto", "//src/main/protobuf:command_line_java_proto", "//src/main/protobuf:command_server_java_proto", + "//src/main/protobuf:execution_graph_java_proto", "//src/main/protobuf:failure_details_java_proto", "//src/main/protobuf:invocation_policy_java_proto", "//src/main/protobuf:option_filters_java_proto", @@ -427,6 +428,7 @@ "//third_party:jsr305", "@com_google_protobuf//:protobuf_java", "@com_google_protobuf//java/util", + "@zstd-jni//:zstd-jni", ], )
diff --git a/src/main/java/com/google/devtools/build/lib/bazel/Bazel.java b/src/main/java/com/google/devtools/build/lib/bazel/Bazel.java index 760d64b..3d10385 100644 --- a/src/main/java/com/google/devtools/build/lib/bazel/Bazel.java +++ b/src/main/java/com/google/devtools/build/lib/bazel/Bazel.java
@@ -78,6 +78,7 @@ com.google.devtools.build.lib.metrics.PostGCMemoryUseRecorder.GcAfterBuildModule.class, com.google.devtools.build.lib.packages.metrics.PackageMetricsModule.class, com.google.devtools.build.lib.metrics.MetricsModule.class, + com.google.devtools.build.lib.runtime.ExecutionGraphDumpModule.class, BazelBuiltinCommandModule.class, com.google.devtools.build.lib.includescanning.IncludeScanningModule.class, // This module needs to be registered after any module submitting tasks with its {@code
diff --git a/src/main/java/com/google/devtools/build/lib/runtime/ExecutionGraphDumpModule.java b/src/main/java/com/google/devtools/build/lib/runtime/ExecutionGraphDumpModule.java new file mode 100644 index 0000000..26a0cc1 --- /dev/null +++ b/src/main/java/com/google/devtools/build/lib/runtime/ExecutionGraphDumpModule.java
@@ -0,0 +1,644 @@ +// Copyright 2022 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.runtime; + +import static java.util.concurrent.TimeUnit.SECONDS; + +import com.github.luben.zstd.ZstdOutputStream; +import com.google.common.annotations.VisibleForTesting; +import com.google.common.base.Preconditions; +import com.google.common.base.Stopwatch; +import com.google.common.collect.ImmutableList; +import com.google.common.collect.Iterables; +import com.google.common.eventbus.AllowConcurrentEvents; +import com.google.common.eventbus.Subscribe; +import com.google.common.flogger.GoogleLogger; +import com.google.devtools.build.lib.actions.ActionInput; +import com.google.devtools.build.lib.actions.Artifact; +import com.google.devtools.build.lib.actions.ExecutionGraph; +import com.google.devtools.build.lib.actions.Spawn; +import com.google.devtools.build.lib.actions.SpawnExecutedEvent; +import com.google.devtools.build.lib.actions.SpawnMetrics; +import com.google.devtools.build.lib.actions.SpawnResult; +import com.google.devtools.build.lib.bugreport.BugReport; +import com.google.devtools.build.lib.bugreport.BugReporter; +import com.google.devtools.build.lib.buildeventstream.BuildEvent.LocalFile.LocalFileCompression; +import com.google.devtools.build.lib.buildeventstream.BuildEvent.LocalFile.LocalFileType; +import com.google.devtools.build.lib.buildeventstream.BuildEventArtifactUploader; +import com.google.devtools.build.lib.buildeventstream.BuildEventArtifactUploader.UploadContext; +import com.google.devtools.build.lib.buildeventstream.BuildEventProtocolOptions; +import com.google.devtools.build.lib.buildtool.BuildResult.BuildToolLogCollection; +import com.google.devtools.build.lib.buildtool.buildevent.BuildCompleteEvent; +import com.google.devtools.build.lib.buildtool.buildevent.ExecutionStartingEvent; +import com.google.devtools.build.lib.cmdline.Label; +import com.google.devtools.build.lib.exec.local.LocalExecutionOptions; +import com.google.devtools.build.lib.runtime.BuildEventArtifactUploaderFactory.InvalidPackagePathSymlinkException; +import com.google.devtools.build.lib.server.FailureDetails.BuildReport; +import com.google.devtools.build.lib.server.FailureDetails.BuildReport.Code; +import com.google.devtools.build.lib.server.FailureDetails.FailureDetail; +import com.google.devtools.build.lib.util.AbruptExitException; +import com.google.devtools.build.lib.util.DetailedExitCode; +import com.google.devtools.build.lib.util.InterruptedFailureDetails; +import com.google.devtools.build.lib.vfs.Path; +import com.google.devtools.common.options.EnumConverter; +import com.google.devtools.common.options.Option; +import com.google.devtools.common.options.OptionDocumentationCategory; +import com.google.devtools.common.options.OptionEffectTag; +import com.google.devtools.common.options.OptionsBase; +import com.google.devtools.common.options.OptionsParsingResult; +import com.google.protobuf.CodedOutputStream; +import java.io.IOException; +import java.io.OutputStream; +import java.time.Duration; +import java.util.Map; +import java.util.Set; +import java.util.TreeSet; +import java.util.UUID; +import java.util.concurrent.BlockingQueue; +import java.util.concurrent.ConcurrentHashMap; +import java.util.concurrent.LinkedBlockingQueue; +import java.util.concurrent.atomic.AtomicInteger; +import java.util.concurrent.atomic.AtomicLong; + +/** Blaze module that writes an partial execution graph with performance data. */ +public class ExecutionGraphDumpModule extends BlazeModule { + + private static final String ACTION_DUMP_NAME = "execution_graph_dump.proto.zst"; + + private static final GoogleLogger logger = GoogleLogger.forEnclosingClass(); + + /** Options for the generated execution graph. */ + public static class ExecutionGraphDumpOptions extends OptionsBase { + @Option( + name = "experimental_execution_graph_log", + documentationCategory = OptionDocumentationCategory.UNDOCUMENTED, + effectTags = {OptionEffectTag.AFFECTS_OUTPUTS}, + defaultValue = "", + help = + "Enabling this flag makes Blaze write a file of all actions executed during a build. " + + "Note that this dump may use a different granularity of actions than other APIs, " + + "and may also contain additional information as necessary to reconstruct the " + + "full dependency graph in combination with other sources of data.") + public String executionGraphLogFile; + + @Option( + name = "experimental_execution_graph_log_dep_type", + converter = DependencyInfoConverter.class, + documentationCategory = OptionDocumentationCategory.UNDOCUMENTED, + effectTags = {OptionEffectTag.UNKNOWN}, + defaultValue = "none", + help = + "Selects what kind of dependency information is reported in the action dump. If 'all'," + + " every inter-action edge will be reported.") + public DependencyInfo depType; + + @Option( + name = "experimental_execution_graph_log_queue_size", + documentationCategory = OptionDocumentationCategory.UNDOCUMENTED, + effectTags = {OptionEffectTag.UNKNOWN}, + defaultValue = "-1", + help = + "The size of the action dump queue, where actions are kept before writing. Larger" + + " sizes will increase peak memory usage, but should decrease queue blocking. -1" + + " means unbounded") + public int queueSize; + } + + /** What level of dependency information to include in the dump. */ + public enum DependencyInfo { + NONE, + RUNFILES, + ALL; + } + + /** Converter for dependency information level. */ + public static class DependencyInfoConverter extends EnumConverter<DependencyInfo> { + public DependencyInfoConverter() { + super(DependencyInfo.class, "dependency edge strategy"); + } + } + + private ActionDumpWriter writer; + private CommandEnvironment env; + + @Override + public Iterable<Class<? extends OptionsBase>> getCommandOptions(Command command) { + return "build".equals(command.name()) + ? ImmutableList.of(ExecutionGraphDumpOptions.class) + : ImmutableList.of(); + } + + @VisibleForTesting + public void setWriter(ActionDumpWriter writer) { + this.writer = writer; + } + + @Override + public void beforeCommand(CommandEnvironment env) { + this.env = env; + + if (env.getCommand().builds()) { + ExecutionGraphDumpOptions options = + Preconditions.checkNotNull( + env.getOptions().getOptions(ExecutionGraphDumpOptions.class), + "ExecutionGraphDumpOptions must be present for ExecutionGraphDumpModule"); + if (!options.executionGraphLogFile.isBlank()) { + env.getEventBus().register(this); + } + } + } + + @Subscribe + public void executionPhaseStarting(ExecutionStartingEvent event) { + try { + // Defer creation of writer until the start of the execution phase. This is done for two + // reasons: + // - The writer's consumer thread spends 4MB on buffer space, and this is wasted retained + // heap during the analysis phase. + // - We want to start the writer only when we have the guarantee we'll shut it down in + // #buildComplete. It'd be unsound to start the writer before BuildStartingEvent, and + // ExecutionStartingEvent definitely postdates that. + writer = createActionDumpWriter(env); + } catch (InvalidPackagePathSymlinkException e) { + DetailedExitCode detailedExitCode = + DetailedExitCode.of(makeReportUploaderNeedsPackagePathsDetail()); + env.getBlazeModuleEnvironment().exit(new AbruptExitException(detailedExitCode, e)); + } catch (ActionDumpFileCreationException e) { + DetailedExitCode detailedExitCode = DetailedExitCode.of(makeReportWriteFailedDetail()); + env.getBlazeModuleEnvironment().exit(new AbruptExitException(detailedExitCode, e)); + } finally { + env = null; + } + } + + @Subscribe + public void buildComplete(BuildCompleteEvent event) { + try { + shutdown(event.getResult().getBuildToolLogCollection()); + } catch (InterruptedException e) { + Thread.currentThread().interrupt(); + // Env might be set to null by a concurrent call to shutdown (via afterCommand). + CommandEnvironment localEnv = env; + if (localEnv != null) { + // Inform environment that we were interrupted: this can override the existing exit code + // in some cases when the environment "finalizes" the exit code. + localEnv + .getBlazeModuleEnvironment() + .exit( + InterruptedFailureDetails.abruptExitException( + "action dump shutdown interrupted", e)); + } + } + } + + @Subscribe + @AllowConcurrentEvents + public void spawnExecuted(SpawnExecutedEvent event) { + // Writer might be modified by a concurrent call to shutdown. See b/184943744. + // It may be possible to get a BuildCompleteEvent before a duplicate Spawn that runs with a + // dynamic execution strategy, in which case we wouldn't export that Spawn. That's ok, since it + // didn't affect the latency of the build. + ActionDumpWriter localWriter = writer; + if (localWriter != null) { + localWriter.enqueue(event); + } + } + + @Override + public void afterCommand() throws AbruptExitException { + // Defensively shut down in case we failed to do so under normal operation. + try { + shutdown(null); + } catch (InterruptedException e) { + throw InterruptedFailureDetails.abruptExitException("action dump shutdown interrupted", e); + } + } + + private void shutdown(BuildToolLogCollection logs) throws InterruptedException { + // Writer might be set to null by a concurrent call to shutdown (via afterCommand). + ActionDumpWriter localWriter = writer; + try { + // Writer might never have been set if the execution phase never happened (see + // executionPhaseStarting). + if (localWriter != null) { + localWriter.shutdown(logs); + } + } finally { + writer = null; + env = null; + } + } + + /** An ActionDumpWriter writes action dump data to a given {@link OutputStream}. */ + @VisibleForTesting + protected abstract static class ActionDumpWriter implements Runnable { + + private ExecutionGraph.Node toProto(SpawnExecutedEvent event) { + ExecutionGraph.Node.Builder nodeBuilder = ExecutionGraph.Node.newBuilder(); + int index = nextIndex.getAndIncrement(); + Spawn spawn = event.getSpawn(); + long startMillis = event.getStartTimeInstant().toEpochMilli(); + SpawnResult spawnResult = event.getSpawnResult(); + nodeBuilder + // TODO(vanja) consider switching prettyPrint() to description() + .setDescription(event.getActionMetadata().prettyPrint()) + .setMnemonic(spawn.getMnemonic()) + .setRunner(spawnResult.getRunnerName()) + .setRunnerSubtype(spawnResult.getRunnerSubtype()); + + if (depType != DependencyInfo.NONE) { + nodeBuilder.setIndex(index); + } + Label ownerLabel = spawn.getResourceOwner().getOwner().getLabel(); + if (ownerLabel != null) { + nodeBuilder.setTargetLabel(ownerLabel.toString()); + } + + SpawnMetrics metrics = spawnResult.getMetrics(); + spawnResult = null; + long totalMillis = metrics.totalTime().toMillis(); + ExecutionGraph.Metrics.Builder metricsBuilder = + ExecutionGraph.Metrics.newBuilder() + .setStartTimestampMillis(startMillis) + .setDurationMillis((int) totalMillis) + .setFetchMillis((int) metrics.fetchTime().toMillis()) + .setParseMillis((int) metrics.parseTime().toMillis()) + .setProcessMillis((int) metrics.executionWallTime().toMillis()) + .setQueueMillis((int) metrics.queueTime().toMillis()) + .setRetryMillis((int) metrics.retryTime().toMillis()) + .setSetupMillis((int) metrics.setupTime().toMillis()) + .setUploadMillis((int) metrics.uploadTime().toMillis()) + .setNetworkMillis((int) metrics.networkTime().toMillis()) + .setOtherMillis((int) metrics.otherTime().toMillis()) + .setProcessOutputsMillis((int) metrics.processOutputsTime().toMillis()); + + for (Map.Entry<Integer, Duration> entry : metrics.retryTimeByError().entrySet()) { + metricsBuilder.putRetryMillisByError(entry.getKey(), (int) entry.getValue().toMillis()); + } + metrics = null; + // maybeAddEdges can take a while, so do it last and try to give up references to any objects + // we won't need. + maybeAddEdges(nodeBuilder, spawn, startMillis, totalMillis, index); + return nodeBuilder.setMetrics(metricsBuilder).build(); + } + + private void maybeAddEdges( + ExecutionGraph.Node.Builder nodeBuilder, + Spawn spawn, + long startMillis, + long totalMillis, + int index) { + if (depType == DependencyInfo.NONE) { + return; + } + + // Spawn.getOutputFiles can be empty. For example, SpawnAction can be made to not report + // outputs, and ExtraAction uses that. In that case, fall back to the owner's primary output. + ActionInput primaryOutput = Iterables.getFirst(spawn.getOutputFiles(), null); + if (primaryOutput == null) { + // Despite the stated contract of getPrimaryOutput(), it can return null, like in + // GrepIncludesAction. + primaryOutput = spawn.getResourceOwner().getPrimaryOutput(); + } + if (primaryOutput != null) { + // If primaryOutput is null, then we know that spawn.getOutputFiles() is also empty, and we + // don't need to do any of the following. + SpawnInfo previousAttempt = outputFileToSpawn.get(primaryOutput); + if (previousAttempt != null) { + // The same action may issue multiple spawns for various reasons: + // + // Different "primary output" for each spawn (hence not entering this if condition): + // - Actions with multiple spawns (e.g. inputs discovering actions). + // - Remote execution splitting the spawn into multiple ones (spawns generating tree + // artifacts). + // + // Running sequentially: + // - Test retries. + // - Java compilation (fallback) after an attempt with a reduced classpath. + // - Retry of a spawn after remote execution failure when using `--local_fallback`. + // + /// Running in parallel: + // - Dynamic execution with `--experimental_local_lockfree_output`--with that setting, + // it is possible for both local and remote spawns to finish and send a corresponding + // event. + if (previousAttempt.finishMs <= startMillis) { + nodeBuilder.setRetryOf(previousAttempt.index); + } else if (localLockFreeOutputEnabled) { + // Special case what could be dynamic execution with + // `--experimental_local_lockfree_output`, skip adding the dependencies for the second + // spawn, but report both spawns. + return; + } else { + // TODO(b/227635546): Remove the bug report once we capture all cases when it can + // fire. + bugReporter.sendNonFatalBugReport( + new IllegalStateException( + String.format( + "See b/227635546. Multiple spawns produced '%s' with overlapping execution" + + " time. Previous index: %s. Current index: %s", + primaryOutput.getExecPathString(), previousAttempt.index, index))); + } + } + + SpawnInfo currentAttempt = new SpawnInfo(index, startMillis + totalMillis); + for (ActionInput output : spawn.getOutputFiles()) { + outputFileToSpawn.put(output, currentAttempt); + } + // Some actions, like tests, don't have their primary output in getOutputFiles(). + outputFileToSpawn.put(primaryOutput, currentAttempt); + } + + // Don't store duplicate deps. This saves some storage space, and uses less memory when the + // action dump is parsed. Using a TreeSet is not slower than a HashSet, and it seems that + // keeping the deps ordered compresses better. See cl/377153712. + Set<Integer> deps = new TreeSet<>(); + for (Artifact runfilesInput : spawn.getRunfilesSupplier().getArtifacts().toList()) { + SpawnInfo dep = outputFileToSpawn.get(runfilesInput); + if (dep != null) { + deps.add(dep.index); + } + } + + if (depType == DependencyInfo.ALL) { + for (ActionInput input : spawn.getInputFiles().toList()) { + SpawnInfo dep = outputFileToSpawn.get(input); + if (dep != null) { + deps.add(dep.index); + } + } + } + nodeBuilder.addAllDependentIndex(deps); + } + + private static final class SpawnInfo { + private final int index; + private final long finishMs; + + private SpawnInfo(int index, long finishMs) { + this.index = index; + this.finishMs = finishMs; + } + } + + private final BugReporter bugReporter; + private final boolean localLockFreeOutputEnabled; + private final Map<ActionInput, SpawnInfo> outputFileToSpawn = new ConcurrentHashMap<>(); + private final DependencyInfo depType; + private final AtomicInteger nextIndex = new AtomicInteger(0); + + // At larger capacities, ArrayBlockingQueue uses slightly less peak memory, but it doesn't + // matter at lower capacities. Wall time performance is the same either way. + // In benchmarks, capacities under 100 start increasing wall time and between 1000 and 100000 + // seem to have roughly the same wall time and memory usage. In the real world, using a queue + // of size 10000 causes many builds to block for a total of more than 100ms. The queue + // entries should be about 256 bytes, so a queue size of 1_000_000 will use up to 256MB, + // but the vast majority of builds don't have that many actions. + private final BlockingQueue<byte[]> queue; + private final AtomicLong blockedMillis = new AtomicLong(0); + private final OutputStream outStream; + private final Thread thread; + + // This queue entry signals that there are no more entries that need to be written. + private static final byte[] INVOCATION_COMPLETED = new byte[0]; + + // Based on benchmarks. 2Mib buffers seem sufficient, and buffers bigger than that don't + // provide much benefit. + private static final int OUTPUT_BUFFER_SIZE = 1 << 21; + + ActionDumpWriter( + BugReporter bugReporter, + boolean localLockFreeOutputEnabled, + OutputStream outStream, + UUID commandId, + DependencyInfo depType, + int queueSize) { + this.bugReporter = bugReporter; + this.localLockFreeOutputEnabled = localLockFreeOutputEnabled; + this.outStream = outStream; + this.depType = depType; + if (queueSize < 0) { + queue = new LinkedBlockingQueue<>(); + } else { + queue = new LinkedBlockingQueue<>(queueSize); + } + this.thread = new Thread(this, "action-graph-writer"); + this.thread.start(); + } + + private static final class ActionDumpQueueFullException extends RuntimeException { + ActionDumpQueueFullException(long blockedMs) { + super("Action dump queue was full and put() blocked for " + blockedMs + "ms."); + } + } + + void enqueue(byte[] entry) { + if (queue.offer(entry)) { + return; + } + Stopwatch sw = Stopwatch.createStarted(); + try { + queue.put(entry); + } catch (InterruptedException e) { + logger.atWarning().atMostEvery(10, SECONDS).withCause(e).log( + "Interrupted while trying to put to queue"); + Thread.currentThread().interrupt(); + } + blockedMillis.addAndGet(sw.elapsed().toMillis()); + } + + public void enqueue(SpawnExecutedEvent event) { + enqueue(toProto(event).toByteArray()); + } + + void shutdown(BuildToolLogCollection logs) throws InterruptedException { + enqueue(INVOCATION_COMPLETED); + long blockedMs = blockedMillis.get(); + if (blockedMs > 100) { + BugReport.sendBugReport(new ActionDumpQueueFullException(blockedMs)); + } + thread.join(); + if (logs != null) { + updateLogs(logs); + } + } + + protected abstract void updateLogs(BuildToolLogCollection logs); + + /** Test hook to allow injecting failures in tests. */ + @VisibleForTesting + ZstdOutputStream createCompressingOutputStream() throws IOException { + // zstd compression at the default level produces 20% smaller outputs than gzip, while being + // faster to compress and decompress. Higher levels get slower quickly, without much benefit + // in size. For example, level 4 produces 1% smaller outputs, but takes twice as long to + // compress in standalone benchmarks. Lower levels quickly increase size, without much benefit + // in speed. For example, level -3 produces 60% bigger outputs, but only runs 10% faster in + // standalone benchmarks. + return new ZstdOutputStream(outStream); + } + + /** + * Saves all gathered information from taskQueue queue to the file. Method is invoked internally + * by the Timer-based thread and at the end of profiling session. + */ + @Override + public void run() { + try { + // Track when we receive the last entry in case there's a failure in the implied #close() + // call on the OutputStream. + boolean receivedLastEntry = false; + try (OutputStream out = createCompressingOutputStream()) { + CodedOutputStream codedOut = CodedOutputStream.newInstance(out, OUTPUT_BUFFER_SIZE); + byte[] data; + while ((data = queue.take()) != INVOCATION_COMPLETED) { + codedOut.writeByteArrayNoTag(data); + } + receivedLastEntry = true; + codedOut.flush(); + } catch (IOException e) { + // Fixing b/117951060 should mitigate, but may happen regardless. + logger.atWarning().withCause(e).log("Failure writing action dump"); + if (!receivedLastEntry) { + while (queue.take() != INVOCATION_COMPLETED) { + // We keep emptying the queue to avoid OOMs or blocking, but we can't write anything. + } + } + } + } catch (InterruptedException e) { + // This thread exits immediately, so there's nothing checking this bit. Just exit silently. + Thread.currentThread().interrupt(); + } + } + } + + private static BuildEventArtifactUploader newUploader( + CommandEnvironment env, BuildEventProtocolOptions bepOptions) + throws InvalidPackagePathSymlinkException { + return env.getRuntime() + .getBuildEventArtifactUploaderFactoryMap() + .select(bepOptions.buildEventUploadStrategy) + .create(env); + } + + private ActionDumpWriter createActionDumpWriter(CommandEnvironment env) + throws InvalidPackagePathSymlinkException, ActionDumpFileCreationException { + OptionsParsingResult parsingResult = env.getOptions(); + BuildEventProtocolOptions bepOptions = + Preconditions.checkNotNull(parsingResult.getOptions(BuildEventProtocolOptions.class)); + ExecutionGraphDumpOptions executionGraphDumpOptions = + Preconditions.checkNotNull(parsingResult.getOptions(ExecutionGraphDumpOptions.class)); + if (bepOptions.streamingLogFileUploads) { + return new StreamingActionDumpWriter( + env.getRuntime().getBugReporter(), + env.getOptions().getOptions(LocalExecutionOptions.class).localLockfreeOutput, + newUploader(env, bepOptions).startUpload(LocalFileType.PERFORMANCE_LOG, null), + env.getCommandId(), + executionGraphDumpOptions.depType, + executionGraphDumpOptions.queueSize); + } + + Path actionGraphFile = + env.getWorkingDirectory().getRelative(executionGraphDumpOptions.executionGraphLogFile); + try { + return new FilesystemActionDumpWriter( + env.getRuntime().getBugReporter(), + env.getOptions().getOptions(LocalExecutionOptions.class).localLockfreeOutput, + actionGraphFile, + env.getCommandId(), + executionGraphDumpOptions.depType, + executionGraphDumpOptions.queueSize); + } catch (IOException e) { + throw new ActionDumpFileCreationException(actionGraphFile, e); + } + } + + private static final class FilesystemActionDumpWriter extends ActionDumpWriter { + private final Path actionGraphFile; + + public FilesystemActionDumpWriter( + BugReporter bugReporter, + boolean localLockFreeOutputEnabled, + Path actionGraphFile, + UUID uuid, + DependencyInfo depType, + int queueSize) + throws IOException { + super( + bugReporter, + localLockFreeOutputEnabled, + actionGraphFile.getOutputStream(), + uuid, + depType, + queueSize); + this.actionGraphFile = actionGraphFile; + } + + @Override + protected void updateLogs(BuildToolLogCollection logs) { + logs.addLocalFile( + ACTION_DUMP_NAME, + actionGraphFile, + LocalFileType.PERFORMANCE_LOG, + LocalFileCompression.NONE); + } + } + + private static FailureDetail makeReportUploaderNeedsPackagePathsDetail() { + return FailureDetail.newBuilder() + .setMessage("could not create action dump uploader due to failed package path resolution") + .setBuildReport( + BuildReport.newBuilder().setCode(Code.BUILD_REPORT_UPLOADER_NEEDS_PACKAGE_PATHS)) + .build(); + } + + private static FailureDetail makeReportWriteFailedDetail() { + return FailureDetail.newBuilder() + .setMessage("could not open action dump file for writing") + .setBuildReport( + BuildReport.newBuilder().setCode(Code.BUILD_REPORT_WRITE_FAILED)) + .build(); + } + + private static class StreamingActionDumpWriter extends ActionDumpWriter { + private final UploadContext uploadContext; + + public StreamingActionDumpWriter( + BugReporter bugReporter, + boolean localLockFreeOutputEnabled, + UploadContext uploadContext, + UUID commandId, + DependencyInfo depType, + int queueSize) { + super( + bugReporter, + localLockFreeOutputEnabled, + uploadContext.getOutputStream(), + commandId, + depType, + queueSize); + this.uploadContext = uploadContext; + } + + @Override + protected void updateLogs(BuildToolLogCollection logs) { + logs.addUriFuture(ACTION_DUMP_NAME, uploadContext.uriFuture()); + } + } + + /** Exception thrown when a FilesystemActionDumpWriter cannot create its output file. */ + private static class ActionDumpFileCreationException extends IOException { + ActionDumpFileCreationException(Path path, IOException e) { + super("could not create new action dump file on filesystem at path: " + path, e); + } + } +}
diff --git a/src/main/protobuf/BUILD b/src/main/protobuf/BUILD index f6d09df..809860f 100644 --- a/src/main/protobuf/BUILD +++ b/src/main/protobuf/BUILD
@@ -21,6 +21,7 @@ "java_compilation", "test_status", "worker_protocol", + "execution_graph", ] [proto_library(
diff --git a/src/main/protobuf/failure_details.proto b/src/main/protobuf/failure_details.proto index 9913f63..7a1b7db 100644 --- a/src/main/protobuf/failure_details.proto +++ b/src/main/protobuf/failure_details.proto
@@ -148,6 +148,7 @@ ExternalDeps external_deps = 181; DiffAwareness diff_awareness = 182; ModqueryCommand modquery_command = 183; + BuildReport build_report = 184; } reserved 102; // For internal use @@ -340,6 +341,19 @@ Code code = 1; } +message BuildReport { + enum Code { + BUILD_REPORT_UNKNOWN = 0 [(metadata) = { exit_code: 37 }]; + BUILD_REPORT_UPLOADER_NEEDS_PACKAGE_PATHS = 1 + [(metadata) = { exit_code: 36 }]; + BUILD_REPORT_WRITE_FAILED = 2 [(metadata) = { exit_code: 36 }]; + } + + Code code = 1; + // Additional data for partial failures might include the build report that + // failed to be written. +} + message PackageOptions { enum Code { reserved 2, 3; // For internal use
diff --git a/src/test/java/com/google/devtools/build/lib/BUILD b/src/test/java/com/google/devtools/build/lib/BUILD index c8d9e2c..2a6f950 100644 --- a/src/test/java/com/google/devtools/build/lib/BUILD +++ b/src/test/java/com/google/devtools/build/lib/BUILD
@@ -129,6 +129,7 @@ "//src/main/java/com/google/devtools/build/lib:runtime/command_line_path_factory", "//src/main/java/com/google/devtools/build/lib:runtime/safe_request_logging", "//src/main/java/com/google/devtools/build/lib/actions", + "//src/main/java/com/google/devtools/build/lib/actions:action_input_helper", "//src/main/java/com/google/devtools/build/lib/actions:action_lookup_data", "//src/main/java/com/google/devtools/build/lib/actions:action_lookup_key", "//src/main/java/com/google/devtools/build/lib/actions:artifacts", @@ -193,6 +194,7 @@ "//src/main/java/net/starlark/java/syntax", "//src/main/protobuf:any_java_proto", "//src/main/protobuf:command_line_java_proto", + "//src/main/protobuf:execution_graph_java_proto", "//src/main/protobuf:failure_details_java_proto", "//src/main/protobuf:invocation_policy_java_proto", "//src/main/protobuf:test_status_java_proto", @@ -201,6 +203,7 @@ "//src/test/java/com/google/devtools/build/lib/analysis/util", "//src/test/java/com/google/devtools/build/lib/buildtool/util", "//src/test/java/com/google/devtools/build/lib/events:testutil", + "//src/test/java/com/google/devtools/build/lib/exec/util", "//src/test/java/com/google/devtools/build/lib/starlark/util", "//src/test/java/com/google/devtools/build/lib/testutil", "//src/test/java/com/google/devtools/build/lib/testutil:JunitUtils", @@ -218,6 +221,7 @@ "//third_party/protobuf:protobuf_java", "@com_google_protobuf//java/util", "@com_google_testparameterinjector//:testparameterinjector", + "@zstd-jni//:zstd-jni", ], )
diff --git a/src/test/java/com/google/devtools/build/lib/runtime/ExecutionGraphDumpModuleTest.java b/src/test/java/com/google/devtools/build/lib/runtime/ExecutionGraphDumpModuleTest.java new file mode 100644 index 0000000..07c30aa --- /dev/null +++ b/src/test/java/com/google/devtools/build/lib/runtime/ExecutionGraphDumpModuleTest.java
@@ -0,0 +1,590 @@ +// Copyright 2022 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.runtime; + +import static com.google.common.truth.Truth.assertThat; +import static com.google.common.truth.extensions.proto.ProtoTruth.assertThat; +import static org.junit.Assume.assumeTrue; +import static org.mockito.ArgumentMatchers.any; +import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.never; +import static org.mockito.Mockito.verify; + +import com.github.luben.zstd.ZstdInputStream; +import com.github.luben.zstd.ZstdOutputStream; +import com.google.common.collect.ImmutableList; +import com.google.common.collect.ImmutableMap; +import com.google.common.collect.ImmutableSet; +import com.google.common.eventbus.EventBus; +import com.google.devtools.build.lib.actions.ActionInput; +import com.google.devtools.build.lib.actions.ActionInputHelper; +import com.google.devtools.build.lib.actions.ActionOwner; +import com.google.devtools.build.lib.actions.Artifact; +import com.google.devtools.build.lib.actions.ArtifactRoot; +import com.google.devtools.build.lib.actions.ArtifactRoot.RootType; +import com.google.devtools.build.lib.actions.ExecutionGraph; +import com.google.devtools.build.lib.actions.ResourceSet; +import com.google.devtools.build.lib.actions.SimpleSpawn; +import com.google.devtools.build.lib.actions.Spawn; +import com.google.devtools.build.lib.actions.SpawnExecutedEvent; +import com.google.devtools.build.lib.actions.SpawnMetrics; +import com.google.devtools.build.lib.actions.SpawnResult; +import com.google.devtools.build.lib.actions.SpawnResult.Status; +import com.google.devtools.build.lib.actions.util.ActionsTestUtil; +import com.google.devtools.build.lib.bugreport.BugReporter; +import com.google.devtools.build.lib.buildtool.BuildResult; +import com.google.devtools.build.lib.buildtool.BuildResult.BuildToolLogCollection; +import com.google.devtools.build.lib.buildtool.buildevent.BuildCompleteEvent; +import com.google.devtools.build.lib.collect.nestedset.NestedSetBuilder; +import com.google.devtools.build.lib.collect.nestedset.Order; +import com.google.devtools.build.lib.exec.util.FakeOwner; +import com.google.devtools.build.lib.exec.util.SpawnBuilder; +import com.google.devtools.build.lib.runtime.ExecutionGraphDumpModule.ActionDumpWriter; +import com.google.devtools.build.lib.runtime.ExecutionGraphDumpModule.DependencyInfo; +import com.google.devtools.build.lib.testutil.FoundationTestCase; +import com.google.devtools.build.lib.util.OS; +import com.google.devtools.build.lib.vfs.PathFragment; +import com.google.testing.junit.testparameterinjector.TestParameter; +import com.google.testing.junit.testparameterinjector.TestParameterInjector; +import java.io.ByteArrayInputStream; +import java.io.ByteArrayOutputStream; +import java.io.IOException; +import java.io.InputStream; +import java.io.OutputStream; +import java.time.Duration; +import java.time.Instant; +import java.util.UUID; +import org.junit.Before; +import org.junit.Test; +import org.junit.runner.RunWith; +import org.mockito.ArgumentCaptor; + +/** Unit tests for {@link ExecutionGraphDumpModule}. */ +@RunWith(TestParameterInjector.class) +public class ExecutionGraphDumpModuleTest extends FoundationTestCase { + private ExecutionGraphDumpModule module; + private ArtifactRoot artifactRoot; + + @Before + public void createModule() { + module = new ExecutionGraphDumpModule(); + } + + @Before + public final void initializeRoots() throws Exception { + artifactRoot = ArtifactRoot.asDerivedRoot(scratch.resolve("/"), RootType.Output, "output"); + } + + private static ImmutableList<ExecutionGraph.Node> parse(ByteArrayOutputStream buffer) + throws IOException { + byte[] data = buffer.toByteArray(); + try (InputStream in = new ZstdInputStream(new ByteArrayInputStream(data))) { + ImmutableList.Builder<ExecutionGraph.Node> nodeListBuilder = new ImmutableList.Builder<>(); + ExecutionGraph.Node node; + while ((node = ExecutionGraph.Node.parseDelimitedFrom(in)) != null) { + nodeListBuilder.add(node); + } + return nodeListBuilder.build(); + } + } + + @Test + public void testOneSpawn() throws IOException { + // zstd is broken on Windows: https://github.com/bazelbuild/bazel/issues/16041 + assumeTrue(OS.getCurrent() != OS.WINDOWS); + + UUID uuid = UUID.randomUUID(); + ByteArrayOutputStream buffer = new ByteArrayOutputStream(); + Spawn spawn = + new SimpleSpawn( + new FakeOwnerWithPrimaryOutput( + "Mnemonic", "Progress message", "//foo", "output/foo/out"), + ImmutableList.of("cmd"), + ImmutableMap.of("env", "value"), + ImmutableMap.of("exec", "value"), + /* inputs= */ NestedSetBuilder.emptySet(Order.STABLE_ORDER), + /* outputs= */ ImmutableSet.of(ActionInputHelper.fromPath("output/foo/out")), + ResourceSet.ZERO); + SpawnResult result = + new SpawnResult.Builder() + .setRunnerName("local") + .setStatus(Status.SUCCESS) + .setExitCode(0) + .setSpawnMetrics( + SpawnMetrics.Builder.forLocalExec() + .setTotalTime(Duration.ofMillis(1234L)) + .setExecutionWallTime(Duration.ofMillis(2345L)) + .setProcessOutputsTime(Duration.ofMillis(3456L)) + .build()) + .build(); + startLogging(eventBus, uuid, buffer, DependencyInfo.NONE); + Instant startTimeInstant = Instant.now(); + module.spawnExecuted(new SpawnExecutedEvent(spawn, result, startTimeInstant)); + module.buildComplete( + new BuildCompleteEvent(new BuildResult(startTimeInstant.toEpochMilli() + 1000))); + + ImmutableList<ExecutionGraph.Node> nodes = parse(buffer); + assertThat(nodes).hasSize(1); + assertThat(nodes.get(0).getTargetLabel()).isEqualTo("//foo:foo"); + assertThat(nodes.get(0).getMnemonic()).isEqualTo("Mnemonic"); + assertThat(nodes.get(0).getMetrics().getDurationMillis()).isEqualTo(1234L); + assertThat(nodes.get(0).getMetrics().getFetchMillis()).isEqualTo(0); + assertThat(nodes.get(0).getMetrics().getProcessOutputsMillis()).isEqualTo(3456); + assertThat(nodes.get(0).getMetrics().getStartTimestampMillis()).isEqualTo(startTimeInstant.toEpochMilli()); + assertThat(nodes.get(0).getIndex()).isEqualTo(0); + assertThat(nodes.get(0).getDependentIndexList()).isEmpty(); + } + + @Test + public void actionDepsWithThreeSpawns() throws IOException { + // zstd is broken on Windows: https://github.com/bazelbuild/bazel/issues/16041 + assumeTrue(OS.getCurrent() != OS.WINDOWS); + + UUID uuid = UUID.randomUUID(); + ByteArrayOutputStream buffer = new ByteArrayOutputStream(); + + ActionInput out1 = ActionInputHelper.fromPath("output/foo/out1"); + ActionInput out2 = ActionInputHelper.fromPath("output/foo/out2"); + ActionInput outTop = ActionInputHelper.fromPath("output/foo/out.top"); + + Spawn spawnOut1 = + new SimpleSpawn( + new FakeOwnerWithPrimaryOutput( + "Mnemonic", "Progress message", "//foo", out1.getExecPathString()), + ImmutableList.of("cmd"), + ImmutableMap.of("env", "value"), + ImmutableMap.of("exec", "value"), + /* inputs= */ NestedSetBuilder.emptySet(Order.STABLE_ORDER), + /* outputs= */ ImmutableSet.of(out1), + ResourceSet.ZERO); + Spawn spawnOut2 = + new SimpleSpawn( + new FakeOwnerWithPrimaryOutput( + "Mnemonic", "Progress message", "//foo", out2.getExecPathString()), + ImmutableList.of("cmd"), + ImmutableMap.of("env", "value"), + ImmutableMap.of("exec", "value"), + /* inputs= */ NestedSetBuilder.emptySet(Order.STABLE_ORDER), + /* outputs= */ ImmutableSet.of(out2), + ResourceSet.ZERO); + Spawn spawnTop = + new SimpleSpawn( + new FakeOwnerWithPrimaryOutput( + "Mnemonic", "Progress message", "//foo", outTop.getExecPathString()), + ImmutableList.of("cmd"), + ImmutableMap.of("env", "value"), + ImmutableMap.of("exec", "value"), + /* inputs= */ NestedSetBuilder.create(Order.COMPILE_ORDER, out1, out2), + /* outputs= */ ImmutableSet.of(outTop), + ResourceSet.ZERO); + SpawnResult result = + new SpawnResult.Builder() + .setRunnerName("local") + .setStatus(Status.SUCCESS) + .setExitCode(0) + .setSpawnMetrics( + SpawnMetrics.Builder.forLocalExec() + .setTotalTime(Duration.ofMillis(1234L)) + .setExecutionWallTime(Duration.ofMillis(2345L)) + .setProcessOutputsTime(Duration.ofMillis(3456L)) + .build()) + .build(); + startLogging(eventBus, uuid, buffer, DependencyInfo.ALL); + Instant startTimeInstant = Instant.now(); + module.spawnExecuted(new SpawnExecutedEvent(spawnOut1, result, startTimeInstant)); + module.spawnExecuted(new SpawnExecutedEvent(spawnOut2, result, startTimeInstant)); + module.spawnExecuted(new SpawnExecutedEvent(spawnTop, result, startTimeInstant)); + module.buildComplete( + new BuildCompleteEvent(new BuildResult(startTimeInstant.plusMillis(1000).toEpochMilli()))); + + ImmutableList<ExecutionGraph.Node> nodes = parse(buffer); + assertThat(nodes).hasSize(3); + + assertThat(nodes.get(0).getIndex()).isEqualTo(0); + assertThat(nodes.get(0).getDependentIndexList()).isEmpty(); + + assertThat(nodes.get(1).getIndex()).isEqualTo(1); + assertThat(nodes.get(1).getDependentIndexList()).isEmpty(); + + assertThat(nodes.get(2).getIndex()).isEqualTo(2); + assertThat(nodes.get(2).getDependentIndexList()).containsExactly(0, 1); + } + + private enum FailingOutputStreamFactory { + CLOSE { + @Override + public ZstdOutputStream get() throws IOException { + return new ZstdOutputStream(OutputStream.nullOutputStream()) { + @Override + public synchronized void close() throws IOException { + throw new IOException("Simulated close failure"); + } + }; + } + }, + /** Called from {@link com.google.protobuf.CodedOutputStream#flush}. */ + WRITE { + @Override + public ZstdOutputStream get() throws IOException { + return new ZstdOutputStream(OutputStream.nullOutputStream()) { + @Override + public synchronized void write(byte[] b, int off, int len) throws IOException { + throw new IOException("oh no!"); + } + }; + } + }; + + abstract ZstdOutputStream get() throws IOException; + } + + /** Regression test for b/218721483. */ + @Test(timeout = 30_000) + public void failureInOutputDoesNotHang( + @TestParameter FailingOutputStreamFactory failingOutputStream) { + // zstd is broken on Windows: https://github.com/bazelbuild/bazel/issues/16041 + assumeTrue(OS.getCurrent() != OS.WINDOWS); + + UUID uuid = UUID.randomUUID(); + ActionDumpWriter writer = + new ActionDumpWriter( + BugReporter.defaultInstance(), + /*localLockFreeOutputEnabled=*/ false, + OutputStream.nullOutputStream(), + uuid, + DependencyInfo.NONE, + -1) { + @Override + protected void updateLogs(BuildToolLogCollection logs) {} + + @Override + protected ZstdOutputStream createCompressingOutputStream() throws IOException { + return failingOutputStream.get(); + } + }; + module.setWriter(writer); + eventBus.register(module); + + Instant startTimeInstant = Instant.now(); + eventBus.post(new BuildCompleteEvent(new BuildResult(startTimeInstant.toEpochMilli() + 1000))); + } + + private void startLogging( + EventBus eventBus, UUID uuid, OutputStream buffer, DependencyInfo depType) { + startLogging( + eventBus, + BugReporter.defaultInstance(), + /*localLockFreeOutputEnabled=*/ false, + uuid, + buffer, + depType); + } + + private void startLogging( + EventBus eventBus, + BugReporter bugReporter, + boolean localLockFreeOutputEnabled, + UUID uuid, + OutputStream buffer, + DependencyInfo depType) { + ActionDumpWriter writer = + new ActionDumpWriter(bugReporter, localLockFreeOutputEnabled, buffer, uuid, depType, -1) { + @Override + protected void updateLogs(BuildToolLogCollection logs) {} + }; + module.setWriter(writer); + eventBus.register(module); + } + + @Test + public void shutDownWithoutStartTolerated() { + eventBus.register(module); + Instant startTimeInstant = Instant.now(); + // Doesn't crash. + eventBus.post(new BuildCompleteEvent(new BuildResult(startTimeInstant.toEpochMilli() + 1000))); + } + + @Test + public void testSpawnWithNullOwnerLabel() throws IOException { + // zstd is broken on Windows: https://github.com/bazelbuild/bazel/issues/16041 + assumeTrue(OS.getCurrent() != OS.WINDOWS); + + UUID uuid = UUID.randomUUID(); + ByteArrayOutputStream buffer = new ByteArrayOutputStream(); + Spawn spawn = + new SimpleSpawn( + new FakeOwnerWithPrimaryOutput( + "Mnemonic", "Progress message", "//unused:label", "output/foo/out") { + @Override + public ActionOwner getOwner() { + return ActionOwner.SYSTEM_ACTION_OWNER; + } + }, + ImmutableList.of("cmd"), + ImmutableMap.of("env", "value"), + ImmutableMap.of("exec", "value"), + /* inputs= */ NestedSetBuilder.emptySet(Order.STABLE_ORDER), + /* outputs= */ ImmutableSet.of(ActionInputHelper.fromPath("output/foo/out")), + ResourceSet.ZERO); + SpawnResult result = + new SpawnResult.Builder() + .setRunnerName("local") + .setStatus(Status.SUCCESS) + .setExitCode(0) + .setSpawnMetrics( + SpawnMetrics.Builder.forLocalExec() + .setTotalTime(Duration.ofMillis(1234L)) + .setExecutionWallTime(Duration.ofMillis(2345L)) + .setProcessOutputsTime(Duration.ofMillis(3456L)) + .build()) + .build(); + startLogging(eventBus, uuid, buffer, DependencyInfo.NONE); + Instant startTimeInstant = Instant.now(); + module.spawnExecuted(new SpawnExecutedEvent(spawn, result, startTimeInstant)); + module.buildComplete( + new BuildCompleteEvent(new BuildResult(startTimeInstant.toEpochMilli() + 1000))); + + ImmutableList<ExecutionGraph.Node> nodes = parse(buffer); + assertThat(nodes).hasSize(1); + assertThat(nodes.get(0).getTargetLabel()).isEmpty(); + } + + @Test + public void multipleSpawnsWithSameOutput_recordsBothSpawnsWithRetry() throws Exception { + // zstd is broken on Windows: https://github.com/bazelbuild/bazel/issues/16041 + assumeTrue(OS.getCurrent() != OS.WINDOWS); + + var buffer = new ByteArrayOutputStream(); + startLogging(eventBus, UUID.randomUUID(), buffer, DependencyInfo.ALL); + SpawnResult localResult = createLocalSpawnResult(Duration.ofMillis(100)); + SpawnResult remoteResult = createRemoteSpawnResult(Duration.ofMillis(200)); + Spawn spawn = + new SpawnBuilder().withOwnerPrimaryOutput(createOutputArtifact("foo/out")).build(); + + module.spawnExecuted(new SpawnExecutedEvent(spawn, localResult, Instant.EPOCH)); + module.spawnExecuted(new SpawnExecutedEvent(spawn, remoteResult, Instant.ofEpochMilli(100))); + module.buildComplete(new BuildCompleteEvent(new BuildResult(1000))); + + ImmutableList<ExecutionGraph.Node> nodes = parse(buffer); + assertThat(nodes) + .containsExactly( + executionGraphNodeBuilderForSpawnBuilderSpawn() + .setIndex(0) + .setMetrics(ExecutionGraph.Metrics.newBuilder() + .setStartTimestampMillis(0) + .setDurationMillis(100) + .setOtherMillis(100)) + .setRunner("local") + .build(), + executionGraphNodeBuilderForSpawnBuilderSpawn() + .setIndex(1) + .setMetrics(ExecutionGraph.Metrics.newBuilder() + .setStartTimestampMillis(100) + .setDurationMillis(200) + .setOtherMillis(200)) + .setRunner("remote") + .setRetryOf(0) + .build()) + .inOrder(); + } + + enum LocalLockFreeOutput { + LOCAL_LOCK_FREE_OUTPUT_ENABLED(/*optionValue=*/ true) { + @Override + void assertBugReport(BugReporter bugReporter) { + verify(bugReporter, never()).sendNonFatalBugReport(any()); + } + }, + LOCAL_LOCK_FREE_OUTPUT_DISABLED(/*optionValue=*/ false) { + @Override + void assertBugReport(BugReporter bugReporter) { + var captor = ArgumentCaptor.forClass(Exception.class); + verify(bugReporter).sendNonFatalBugReport(captor.capture()); + assertThat(captor.getValue()) + .hasMessageThat() + .contains("Multiple spawns produced 'output/foo/out' with overlapping execution time."); + } + }; + + LocalLockFreeOutput(boolean optionValue) { + this.optionValue = optionValue; + } + + private final boolean optionValue; + + abstract void assertBugReport(BugReporter bugReporter); + } + + @Test + public void multipleSpawnsWithSameOutput_overlapping_recordsBothSpawnsWithoutRetry( + @TestParameter LocalLockFreeOutput localLockFreeOutput) throws Exception { + // zstd is broken on Windows: https://github.com/bazelbuild/bazel/issues/16041 + assumeTrue(OS.getCurrent() != OS.WINDOWS); + + var buffer = new ByteArrayOutputStream(); + BugReporter bugReporter = mock(BugReporter.class); + startLogging( + eventBus, + bugReporter, + localLockFreeOutput.optionValue, + UUID.randomUUID(), + buffer, + DependencyInfo.ALL); + SpawnResult localResult = createLocalSpawnResult(Duration.ofMillis(100)); + SpawnResult remoteResult = createRemoteSpawnResult(Duration.ofMillis(200)); + Spawn spawn = + new SpawnBuilder().withOwnerPrimaryOutput(createOutputArtifact("foo/out")).build(); + + module.spawnExecuted(new SpawnExecutedEvent(spawn, localResult, Instant.EPOCH)); + module.spawnExecuted(new SpawnExecutedEvent(spawn, remoteResult, Instant.ofEpochMilli(10))); + module.buildComplete(new BuildCompleteEvent(new BuildResult(1000))); + + ImmutableList<ExecutionGraph.Node> nodes = parse(buffer); + assertThat(nodes) + .containsExactly( + executionGraphNodeBuilderForSpawnBuilderSpawn() + .setIndex(0) + .setMetrics(ExecutionGraph.Metrics.newBuilder() + .setStartTimestampMillis(0) + .setDurationMillis(100) + .setOtherMillis(100)) + .setRunner("local") + .build(), + executionGraphNodeBuilderForSpawnBuilderSpawn() + .setIndex(1) + .setMetrics(ExecutionGraph.Metrics.newBuilder() + .setStartTimestampMillis(10) + .setDurationMillis(200) + .setOtherMillis(200)) + .setRunner("remote") + .build()) + .inOrder(); + localLockFreeOutput.assertBugReport(bugReporter); + } + + @Test + public void multipleSpawnsWithSameOutput_overlapping_ignoresSecondSpawnForDependencies() + throws Exception { + // zstd is broken on Windows: https://github.com/bazelbuild/bazel/issues/16041 + assumeTrue(OS.getCurrent() != OS.WINDOWS); + + var buffer = new ByteArrayOutputStream(); + startLogging( + eventBus, + BugReporter.defaultInstance(), + /*localLockFreeOutputEnabled=*/ true, + UUID.randomUUID(), + buffer, + DependencyInfo.ALL); + SpawnResult localResult = createLocalSpawnResult(Duration.ofMillis(100)); + SpawnResult remoteResult = createRemoteSpawnResult(Duration.ofMillis(200)); + Artifact input = createOutputArtifact("foo/input"); + Spawn spawn = new SpawnBuilder().withOwnerPrimaryOutput(input).build(); + Spawn dependentSpawn = + new SpawnBuilder() + .withOwnerPrimaryOutput(createOutputArtifact("foo/output")) + .withInput(input) + .build(); + SpawnResult dependentResult = createRemoteSpawnResult(Duration.ofMillis(300)); + + module.spawnExecuted(new SpawnExecutedEvent(spawn, localResult, Instant.EPOCH)); + module.spawnExecuted(new SpawnExecutedEvent(spawn, remoteResult, Instant.ofEpochMilli(10))); + module.spawnExecuted( + new SpawnExecutedEvent(dependentSpawn, dependentResult, Instant.ofEpochMilli(300))); + module.buildComplete(new BuildCompleteEvent(new BuildResult(1000))); + + ImmutableList<ExecutionGraph.Node> nodes = parse(buffer); + assertThat(nodes) + .containsExactly( + executionGraphNodeBuilderForSpawnBuilderSpawn() + .setIndex(0) + .setMetrics(ExecutionGraph.Metrics.newBuilder() + .setStartTimestampMillis(0) + .setDurationMillis(100) + .setOtherMillis(100)) + .setRunner("local") + .build(), + executionGraphNodeBuilderForSpawnBuilderSpawn() + .setIndex(1) + .setMetrics(ExecutionGraph.Metrics.newBuilder() + .setStartTimestampMillis(10) + .setDurationMillis(200) + .setOtherMillis(200)) + .setRunner("remote") + .build(), + executionGraphNodeBuilderForSpawnBuilderSpawn() + .setIndex(2) + .setMetrics(ExecutionGraph.Metrics.newBuilder() + .setStartTimestampMillis(300) + .setDurationMillis(300) + .setOtherMillis(300)) + .setRunner("remote") + .addDependentIndex(0) + .build()) + .inOrder(); + } + + private class FakeOwnerWithPrimaryOutput extends FakeOwner { + + private final String primaryOutput; + + public FakeOwnerWithPrimaryOutput( + String mnemonic, String progressMessage, String ownerLabel, String primaryOutput) { + super(mnemonic, progressMessage, ownerLabel); + this.primaryOutput = primaryOutput; + } + + @Override + public Artifact getPrimaryOutput() { + return ActionsTestUtil.createArtifactWithExecPath( + artifactRoot, PathFragment.create(primaryOutput)); + } + } + + private Artifact createOutputArtifact(String rootRelativePath) { + return ActionsTestUtil.createArtifactWithExecPath( + artifactRoot, artifactRoot.getExecPath().getRelative(rootRelativePath)); + } + + private SpawnResult createLocalSpawnResult(Duration totalTime) { + return new SpawnResult.Builder() + .setRunnerName("local") + .setStatus(Status.SUCCESS) + .setExitCode(0) + .setSpawnMetrics(SpawnMetrics.Builder.forLocalExec().setTotalTime(totalTime).build()) + .build(); + } + + private SpawnResult createRemoteSpawnResult(Duration totalTime) { + return new SpawnResult.Builder() + .setRunnerName("remote") + .setStatus(Status.SUCCESS) + .setExitCode(0) + .setSpawnMetrics(SpawnMetrics.Builder.forRemoteExec().setTotalTime(totalTime).build()) + .build(); + } + + /** + * Creates a {@link ExecutionGraph.Node.Builder} with pre-populated defaults for spawns created + * using {@link SpawnBuilder}. + */ + private ExecutionGraph.Node.Builder executionGraphNodeBuilderForSpawnBuilderSpawn() { + return ExecutionGraph.Node.newBuilder() + .setDescription("action 'progress message'") + .setTargetLabel("//dummy:label") + .setMnemonic("Mnemonic") + // This comes from SpawnResult.Builder, which defaults to an empty string. + .setRunnerSubtype(""); + } +}