From 3018d2c04321ea03a5c5656a97253358f6c783e4 Mon Sep 17 00:00:00 2001 From: Googler Date: Tue, 7 Nov 2023 04:26:11 -0800 Subject: [PATCH] Delete the now redundant --experimental_execution_log_file flag, and optimize creation of unsorted logs. Since we're about to introduce a new log format (see https://github.com/bazelbuild/bazel/issues/18643), let's take this opportunity to clean up the command line API. Avoid a pointless copy of the execution log, if no sorting is requested, by writing directly into the requested output binary path. If a temporary file is necessary, write it to a well-known path in the output base, and delete it after conversions are successful; this ensures that large temporary files don't accumulate in /tmp. RELNOTES[INC]: Delete the --experimental_execution_log_file flag. Use --execution_log_binary_file in conjunction with --noexecution_log_sort instead. PiperOrigin-RevId: 580132026 Change-Id: Icca827260176b3ea804384d2bed4a56ce85cfc14 --- .../com/google/devtools/build/lib/bazel/BUILD | 2 + .../build/lib/bazel/SpawnLogModule.java | 162 ++++++++++-------- .../build/lib/exec/ExecutionOptions.java | 43 ++--- .../devtools/build/lib/util/OptionsUtils.java | 23 ++- .../util/io/MessageOutputStreamWrapper.java | 4 +- src/test/shell/bazel/bazel_execlog_test.sh | 9 +- 6 files changed, 130 insertions(+), 113 deletions(-) diff --git a/src/main/java/com/google/devtools/build/lib/bazel/BUILD b/src/main/java/com/google/devtools/build/lib/bazel/BUILD index c730d7956b7c77..7de94c3cf50b2e 100644 --- a/src/main/java/com/google/devtools/build/lib/bazel/BUILD +++ b/src/main/java/com/google/devtools/build/lib/bazel/BUILD @@ -142,6 +142,8 @@ java_library( "//src/main/java/com/google/devtools/build/lib/vfs", "//src/main/protobuf:failure_details_java_proto", "//src/main/protobuf:spawn_java_proto", + "//third_party:guava", + "//third_party:jsr305", ], ) diff --git a/src/main/java/com/google/devtools/build/lib/bazel/SpawnLogModule.java b/src/main/java/com/google/devtools/build/lib/bazel/SpawnLogModule.java index 6a33aa9ffc5fab..16840f58cd7a56 100644 --- a/src/main/java/com/google/devtools/build/lib/bazel/SpawnLogModule.java +++ b/src/main/java/com/google/devtools/build/lib/bazel/SpawnLogModule.java @@ -13,6 +13,8 @@ // limitations under the License. package com.google.devtools.build.lib.bazel; +import static com.google.common.base.Preconditions.checkNotNull; + import com.google.devtools.build.lib.bazel.execlog.StableSort; import com.google.devtools.build.lib.buildtool.BuildRequest; import com.google.devtools.build.lib.events.Event; @@ -30,96 +32,101 @@ import com.google.devtools.build.lib.util.AbruptExitException; import com.google.devtools.build.lib.util.DetailedExitCode; import com.google.devtools.build.lib.util.io.AsynchronousFileOutputStream; +import com.google.devtools.build.lib.util.io.MessageOutputStream; import com.google.devtools.build.lib.util.io.MessageOutputStreamWrapper.BinaryOutputStreamWrapper; import com.google.devtools.build.lib.util.io.MessageOutputStreamWrapper.JsonOutputStreamWrapper; import com.google.devtools.build.lib.util.io.MessageOutputStreamWrapper.MessageOutputStreamCollection; -import com.google.devtools.build.lib.vfs.FileSystem; import com.google.devtools.build.lib.vfs.Path; -import java.io.File; import java.io.IOException; import java.io.InputStream; +import javax.annotation.Nullable; -/** - * Module providing on-demand spawn logging. - */ +/** Module providing on-demand spawn logging. */ public final class SpawnLogModule extends BlazeModule { + @Nullable private SpawnLogContext spawnLogContext; + + /** Output path for the raw output stream. */ + @Nullable private Path rawOutputPath; + + /** Output stream to write directly into during execution. */ + @Nullable private MessageOutputStream rawOutputStream; + /** - * SpawnLogContext will log to a temporary file as the execution is being performed. rawOutput is - * the path to that temporary file. + * Output streams to convert the raw output into after the execution is done. + * + *

We open the streams at the beginning of the command so that any errors (e.g., unwritable + * location) are surfaced before execution begins. */ - private SpawnLogContext spawnLogContext; - - private Path rawOutput; + private MessageOutputStreamCollection convertedOutputStreams; /** - * After the execution is done, the temporary file contents will be sorted and logged as the user - * requested, to binary and/or json files. We will open the streams at the beginning of the - * command so that any errors (e.g., unwritable location) will be surfaced before the execution - * begins. + * Whether the raw outputpath is not one of the requested output files, and may be safely deleted + * if conversions are successful. */ - private MessageOutputStreamCollection outputStreams; + private boolean mayDeleteRawOutputPath; private CommandEnvironment env; private void clear() { spawnLogContext = null; - outputStreams = new MessageOutputStreamCollection(); - rawOutput = null; + rawOutputPath = null; + rawOutputStream = null; + convertedOutputStreams = new MessageOutputStreamCollection(); + mayDeleteRawOutputPath = false; env = null; } private void initOutputs(CommandEnvironment env) throws IOException { clear(); - this.env = env; ExecutionOptions executionOptions = env.getOptions().getOptions(ExecutionOptions.class); - if (executionOptions == null) { + if (executionOptions == null + || (executionOptions.executionLogBinaryFile == null + && executionOptions.executionLogJsonFile == null)) { + // No logging requested. return; } - FileSystem fileSystem = env.getRuntime().getFileSystem(); + + this.env = env; + Path workingDirectory = env.getWorkingDirectory(); + Path outputBase = env.getOutputBase(); + + // Set up the raw output stream. + // This stream performs the writes in a separate thread to avoid blocking execution. + // If the unsorted binary format was requested, use the respective output path to avoid a + // pointless conversion at the end. Otherwise, use a temporary path. + if (executionOptions.executionLogBinaryFile != null && !executionOptions.executionLogSort) { + rawOutputPath = workingDirectory.getRelative(executionOptions.executionLogBinaryFile); + mayDeleteRawOutputPath = true; + } else { + rawOutputPath = outputBase.getRelative("execution.log"); + mayDeleteRawOutputPath = false; + } + rawOutputStream = new AsynchronousFileOutputStream(rawOutputPath); - if (executionOptions.executionLogBinaryFile != null - && !executionOptions.executionLogBinaryFile.isEmpty()) { - outputStreams.addStream( + // Set up the binary output stream, if distinct from the raw output stream. + if (executionOptions.executionLogBinaryFile != null && executionOptions.executionLogSort) { + convertedOutputStreams.addStream( new BinaryOutputStreamWrapper( workingDirectory .getRelative(executionOptions.executionLogBinaryFile) .getOutputStream())); } - if (executionOptions.executionLogJsonFile != null - && !executionOptions.executionLogJsonFile.isEmpty()) { - outputStreams.addStream( + // Set up the text output stream. + if (executionOptions.executionLogJsonFile != null) { + convertedOutputStreams.addStream( new JsonOutputStreamWrapper( workingDirectory .getRelative(executionOptions.executionLogJsonFile) .getOutputStream())); } - AsynchronousFileOutputStream outStream = null; - if (executionOptions.executionLogFile != null && !executionOptions.executionLogFile.isEmpty()) { - rawOutput = workingDirectory.getRelative(executionOptions.executionLogFile); - outStream = - new AsynchronousFileOutputStream( - workingDirectory.getRelative(executionOptions.executionLogFile)); - } else if (!outputStreams.isEmpty()) { - // Execution log requested but raw log file not specified - File file = File.createTempFile("exec", ".log"); - rawOutput = fileSystem.getPath(file.getAbsolutePath()); - outStream = new AsynchronousFileOutputStream(rawOutput); - } - - if (outStream == null) { - // No logging needed - clear(); - return; - } - spawnLogContext = new SpawnLogContext( env.getExecRoot().asFragment(), - outStream, + rawOutputStream, env.getOptions().getOptions(ExecutionOptions.class), env.getOptions().getOptions(RemoteOptions.class), env.getRuntime().getFileSystem().getDigestFunction(), @@ -158,37 +165,48 @@ public void executorInit(CommandEnvironment env, BuildRequest request, ExecutorB @Override public void afterCommand() throws AbruptExitException { + if (spawnLogContext == null) { + // No logging requested. + return; + } + + checkNotNull(rawOutputPath); + boolean done = false; - if (spawnLogContext != null) { - try { - spawnLogContext.close(); - if (!outputStreams.isEmpty()) { - InputStream in = rawOutput.getInputStream(); - if (spawnLogContext.shouldSort()) { - StableSort.stableSort(in, outputStreams); - } else { - while (in.available() > 0) { - SpawnExec ex = SpawnExec.parseDelimitedFrom(in); - outputStreams.write(ex); - } + try { + spawnLogContext.close(); + if (!convertedOutputStreams.isEmpty()) { + InputStream in = rawOutputPath.getInputStream(); + if (spawnLogContext.shouldSort()) { + StableSort.stableSort(in, convertedOutputStreams); + } else { + while (in.available() > 0) { + SpawnExec ex = SpawnExec.parseDelimitedFrom(in); + convertedOutputStreams.write(ex); } - outputStreams.close(); } - done = true; - } catch (IOException e) { - String message = e.getMessage() == null ? "Error writing execution log" : e.getMessage(); - throw new AbruptExitException( - createDetailedExitCode(message, Code.EXECUTION_LOG_WRITE_FAILURE), e); - } finally { - if (!done && !outputStreams.isEmpty()) { - env.getReporter() - .handle( - Event.warn( - "Execution log might not have been populated. Raw execution log is at " - + rawOutput)); + convertedOutputStreams.close(); + } + done = true; + } catch (IOException e) { + String message = e.getMessage() == null ? "Error writing execution log" : e.getMessage(); + throw new AbruptExitException( + createDetailedExitCode(message, Code.EXECUTION_LOG_WRITE_FAILURE), e); + } finally { + if (!done && !convertedOutputStreams.isEmpty()) { + env.getReporter() + .handle( + Event.warn( + "Execution log might not have been populated. Raw execution log is at " + + rawOutputPath)); + } else if (mayDeleteRawOutputPath) { + try { + rawOutputPath.delete(); + } catch (IOException e) { + // Intentionally ignored. } - clear(); } + clear(); } } diff --git a/src/main/java/com/google/devtools/build/lib/exec/ExecutionOptions.java b/src/main/java/com/google/devtools/build/lib/exec/ExecutionOptions.java index cd6038ee83378c..5b688ba8cf8a17 100644 --- a/src/main/java/com/google/devtools/build/lib/exec/ExecutionOptions.java +++ b/src/main/java/com/google/devtools/build/lib/exec/ExecutionOptions.java @@ -389,36 +389,18 @@ public boolean usingLocalTestJobs() { ) public boolean statsSummary; - @Option( - name = "experimental_execution_log_file", - defaultValue = "null", - category = "verbosity", - documentationCategory = OptionDocumentationCategory.UNCATEGORIZED, - effectTags = {OptionEffectTag.UNKNOWN}, - converter = OptionsUtils.PathFragmentConverter.class, - help = - "Log the executed spawns into this file as delimited Spawn protos, according to " - + "src/main/protobuf/spawn.proto. This file is written in order of the execution " - + "of the Spawns. Related flags:" - + " --execution_log_binary_file (ordered binary protobuf format)," - + " --execution_log_json_file (ordered text json format)," - + " --subcommands (for displaying subcommands in terminal output).") - public PathFragment executionLogFile; - @Option( name = "execution_log_binary_file", defaultValue = "null", category = "verbosity", documentationCategory = OptionDocumentationCategory.UNCATEGORIZED, effectTags = {OptionEffectTag.UNKNOWN}, - converter = OptionsUtils.PathFragmentConverter.class, + converter = OptionsUtils.EmptyToNullPathFragmentConverter.class, help = "Log the executed spawns into this file as delimited Spawn protos, according to" - + " src/main/protobuf/spawn.proto. The log is first written unordered and is then," - + " at the end of the invocation, sorted in a stable order (can be CPU and memory" - + " intensive). Related flags:" - + " --execution_log_json_file (ordered text json format)," - + " --experimental_execution_log_file (unordered binary protobuf format)," + + " src/main/protobuf/spawn.proto. Related flags:" + + " --execution_log_json_file (text JSON format)," + + " --execution_log_sort (whether to sort the execution log)," + " --subcommands (for displaying subcommands in terminal output).") public PathFragment executionLogBinaryFile; @@ -428,14 +410,12 @@ public boolean usingLocalTestJobs() { category = "verbosity", documentationCategory = OptionDocumentationCategory.UNCATEGORIZED, effectTags = {OptionEffectTag.UNKNOWN}, - converter = OptionsUtils.PathFragmentConverter.class, + converter = OptionsUtils.EmptyToNullPathFragmentConverter.class, help = - "Log the executed spawns into this file as json representation of the delimited Spawn" - + " protos, according to src/main/protobuf/spawn.proto. The log is first written" - + " unordered and is then, at the end of the invocation, sorted in a stable order" - + " (can be CPU and memory intensive). Related flags:" - + " Related flags: --execution_log_binary_file (ordered binary protobuf format)," - + " --experimental_execution_log_file (unordered binary protobuf format)," + "Log the executed spawns into this file as a JSON representation of the delimited Spawn" + + " protos, according to src/main/protobuf/spawn.proto. Related flags:" + + " --execution_log_binary_file (binary protobuf format)," + + " --execution_log_sort (whether to sort the execution log)," + " --subcommands (for displaying subcommands in terminal output).") public PathFragment executionLogJsonFile; @@ -445,8 +425,9 @@ public boolean usingLocalTestJobs() { documentationCategory = OptionDocumentationCategory.UNCATEGORIZED, effectTags = {OptionEffectTag.UNKNOWN}, help = - "Whether to sort the execution log. Set to false to improve memory" - + " performance, at the cost of producing the log in nondeterministic" + "Whether to sort the execution log, making it easier to compare logs across invocations." + + " Set to false to avoid potentially significant CPU and memory usage at the end of" + + " the invocation, at the cost of producing the log in nondeterministic execution" + " order.") public boolean executionLogSort; diff --git a/src/main/java/com/google/devtools/build/lib/util/OptionsUtils.java b/src/main/java/com/google/devtools/build/lib/util/OptionsUtils.java index d5527849944499..54045f68310fe3 100644 --- a/src/main/java/com/google/devtools/build/lib/util/OptionsUtils.java +++ b/src/main/java/com/google/devtools/build/lib/util/OptionsUtils.java @@ -109,6 +109,24 @@ public String getTypeDescription() { } } + /** Converter from String to PathFragment. If the input is empty returns {@code null} instead. */ + public static class EmptyToNullPathFragmentConverter extends Converter.Contextless { + + @Override + @Nullable + public PathFragment convert(String input) throws OptionsParsingException { + if (input.isEmpty()) { + return null; + } + return convertOptionsPathFragment(input); + } + + @Override + public String getTypeDescription() { + return "a path"; + } + } + /** Converter from String to PathFragment requiring the provided path to be absolute. */ public static class AbsolutePathFragmentConverter extends Converter.Contextless { @@ -127,7 +145,10 @@ public String getTypeDescription() { } } - /** Converter from String to PathFragment. If the input is empty returns {@code null} instead. */ + /** + * Converter from String to PathFragment requiring the provided path to be relative. If the input + * is empty returns {@code null} instead. + */ public static class EmptyToNullRelativePathFragmentConverter extends Converter.Contextless { diff --git a/src/main/java/com/google/devtools/build/lib/util/io/MessageOutputStreamWrapper.java b/src/main/java/com/google/devtools/build/lib/util/io/MessageOutputStreamWrapper.java index 58aea9c7865c40..58aac1721c7447 100644 --- a/src/main/java/com/google/devtools/build/lib/util/io/MessageOutputStreamWrapper.java +++ b/src/main/java/com/google/devtools/build/lib/util/io/MessageOutputStreamWrapper.java @@ -22,9 +22,9 @@ import java.nio.charset.StandardCharsets; import java.util.ArrayList; -/** Creating a MessageOutputStream from an OutputStream */ +/** Creates a MessageOutputStream from an OutputStream. */ public class MessageOutputStreamWrapper { - /** Outputs the messages in binary format */ + /** Outputs the messages in delimited protobuf binary format. */ public static class BinaryOutputStreamWrapper implements MessageOutputStream { private final OutputStream stream; diff --git a/src/test/shell/bazel/bazel_execlog_test.sh b/src/test/shell/bazel/bazel_execlog_test.sh index 64eed87e4df5ff..ceb766391dc486 100755 --- a/src/test/shell/bazel/bazel_execlog_test.sh +++ b/src/test/shell/bazel/bazel_execlog_test.sh @@ -115,7 +115,7 @@ genrule( cmd = "echo hello > $(location out.txt)" ) EOF - bazel build //:all --experimental_execution_log_file output 2>&1 >> $TEST_log || fail "could not build" + bazel build //:all --execution_log_binary_file output 2>&1 >> $TEST_log || fail "could not build" wc output || fail "no output produced" } @@ -135,7 +135,7 @@ genrule( cmd = "echo hello > $(location out.txt)" ) EOF - bazel build //:rule --experimental_execution_log_file output 2>&1 >> $TEST_log || fail "could not build" + bazel build //:rule --execution_log_binary_file output 2>&1 >> $TEST_log || fail "could not build" [[ -e output ]] || fail "no output produced" } @@ -147,11 +147,6 @@ genrule( cmd = "echo hello > $(location out.txt)" ) EOF - bazel build //:all --experimental_execution_log_file=output --experimental_execution_log_file= 2>&1 >> $TEST_log || fail "could not build" - if [[ -e output ]]; then - fail "file shouldn't exist" - fi - bazel build //:all --execution_log_json_file=output --execution_log_json_file= 2>&1 >> $TEST_log || fail "could not build" if [[ -e output ]]; then fail "file shouldn't exist"