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 #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

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",
     ],
 )
 

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.
+   *
+   * <p>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();
     }
   }
 

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;
 

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<PathFragment> {
+
+    @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<PathFragment> {
 
@@ -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<PathFragment> {
 

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;
 

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"