Add profiling to execution_log creation, writing, sorting.

This might help to understand when it is costly, see also #18643 PiperOrigin-RevId: 542194475 Change-Id: I85932d8a5d7a832ee4675722642deb675f7db81f
bazelbuild · Jun 21, 2023 · c2e25ea · c2e25ea
1 parent edeb037
commit c2e25ea
Show file tree

Hide file tree

Showing 4 changed files with 37 additions and 21 deletions.
diff --git a/src/main/java/com/google/devtools/build/lib/bazel/execlog/BUILD b/src/main/java/com/google/devtools/build/lib/bazel/execlog/BUILD
@@ -15,6 +15,7 @@ java_library(
     name = "stable_sort",
     srcs = glob(["*.java"]),
     deps = [
+        "//src/main/java/com/google/devtools/build/lib/profiler",
         "//src/main/java/com/google/devtools/build/lib/util/io",
         "//src/main/protobuf:spawn_java_proto",
         "//third_party:guava",

diff --git a/src/main/java/com/google/devtools/build/lib/bazel/execlog/StableSort.java b/src/main/java/com/google/devtools/build/lib/bazel/execlog/StableSort.java
@@ -19,6 +19,8 @@
 import com.google.common.collect.MultimapBuilder;
 import com.google.devtools.build.lib.exec.Protos.File;
 import com.google.devtools.build.lib.exec.Protos.SpawnExec;
+import com.google.devtools.build.lib.profiler.Profiler;
+import com.google.devtools.build.lib.profiler.SilentCloseable;
 import com.google.devtools.build.lib.util.io.MessageOutputStream;
 import java.io.IOException;
 import java.io.InputStream;
@@ -54,7 +56,13 @@ private static ImmutableList<SpawnExec> read(InputStream in) throws IOException
    * output. We assume that there are no cyclic dependencies.
    */
   public static void stableSort(InputStream in, MessageOutputStream out) throws IOException {
-    stableSort(read(in), out);
+    try (SilentCloseable c = Profiler.instance().profile("stableSort")) {
+      ImmutableList<SpawnExec> inputs;
+      try (SilentCloseable c2 = Profiler.instance().profile("stableSort/read")) {
+        inputs = read(in);
+      }
+      stableSort(inputs, out);
+    }
   }
 
   private static void stableSort(List<SpawnExec> inputs, MessageOutputStream out)

diff --git a/src/main/java/com/google/devtools/build/lib/exec/BUILD b/src/main/java/com/google/devtools/build/lib/exec/BUILD
@@ -260,6 +260,7 @@ java_library(
         "//src/main/java/com/google/devtools/build/lib/actions:artifacts",
         "//src/main/java/com/google/devtools/build/lib/actions:file_metadata",
         "//src/main/java/com/google/devtools/build/lib/analysis/platform:platform_utils",
+        "//src/main/java/com/google/devtools/build/lib/profiler",
         "//src/main/java/com/google/devtools/build/lib/remote/options",
         "//src/main/java/com/google/devtools/build/lib/util/io",
         "//src/main/java/com/google/devtools/build/lib/vfs",

diff --git a/src/main/java/com/google/devtools/build/lib/exec/SpawnLogContext.java b/src/main/java/com/google/devtools/build/lib/exec/SpawnLogContext.java
@@ -31,6 +31,8 @@
 import com.google.devtools.build.lib.exec.Protos.Digest;
 import com.google.devtools.build.lib.exec.Protos.File;
 import com.google.devtools.build.lib.exec.Protos.SpawnExec;
+import com.google.devtools.build.lib.profiler.Profiler;
+import com.google.devtools.build.lib.profiler.SilentCloseable;
 import com.google.devtools.build.lib.remote.options.RemoteOptions;
 import com.google.devtools.build.lib.util.io.MessageOutputStream;
 import com.google.devtools.build.lib.vfs.DigestHashFunction;
@@ -100,7 +102,7 @@ public void logSpawn(
       builder.addEnvironmentVariablesBuilder().setName(var).setValue(env.get(var));
     }
 
-    try {
+    try (SilentCloseable c = Profiler.instance().profile("logSpawn/inputs")) {
       for (Map.Entry<PathFragment, ActionInput> e : inputMap.entrySet()) {
         ActionInput input = e.getValue();
         if (input instanceof VirtualActionInput.EmptyActionInput) {
@@ -117,24 +119,26 @@ public void logSpawn(
     } catch (IOException e) {
       logger.atWarning().withCause(e).log("Error computing spawn inputs");
     }
-    ArrayList<String> outputPaths = new ArrayList<>();
-    for (ActionInput output : spawn.getOutputFiles()) {
-      outputPaths.add(output.getExecPathString());
-    }
-    Collections.sort(outputPaths);
-    builder.addAllListedOutputs(outputPaths);
-    for (Map.Entry<Path, ActionInput> e : existingOutputs.entrySet()) {
-      Path path = e.getKey();
-      if (path.isDirectory()) {
-        listDirectoryContents(path, builder::addActualOutputs, inputMetadataProvider);
-      } else {
-        File.Builder outputBuilder = builder.addActualOutputsBuilder();
-        outputBuilder.setPath(path.relativeTo(execRoot).toString());
-        try {
-          outputBuilder.setDigest(
-              computeDigest(e.getValue(), path, inputMetadataProvider, xattrProvider));
-        } catch (IOException ex) {
-          logger.atWarning().withCause(ex).log("Error computing spawn event output properties");
+    try (SilentCloseable c = Profiler.instance().profile("logSpawn/outputs")) {
+      ArrayList<String> outputPaths = new ArrayList<>();
+      for (ActionInput output : spawn.getOutputFiles()) {
+        outputPaths.add(output.getExecPathString());
+      }
+      Collections.sort(outputPaths);
+      builder.addAllListedOutputs(outputPaths);
+      for (Map.Entry<Path, ActionInput> e : existingOutputs.entrySet()) {
+        Path path = e.getKey();
+        if (path.isDirectory()) {
+          listDirectoryContents(path, builder::addActualOutputs, inputMetadataProvider);
+        } else {
+          File.Builder outputBuilder = builder.addActualOutputsBuilder();
+          outputBuilder.setPath(path.relativeTo(execRoot).toString());
+          try {
+            outputBuilder.setDigest(
+                computeDigest(e.getValue(), path, inputMetadataProvider, xattrProvider));
+          } catch (IOException ex) {
+            logger.atWarning().withCause(ex).log("Error computing spawn event output properties");
+          }
         }
       }
     }
@@ -219,7 +223,9 @@ public void logSpawn(
       }
     }
 
-    executionLog.write(builder.build());
+    try (SilentCloseable c = Profiler.instance().profile("logSpawn/write")) {
+      executionLog.write(builder.build());
+    }
   }
 
   private static com.google.protobuf.Duration millisToProto(int t) {