RemoteSpawnRunner: record inbetween phases in timing profile

sluongng · copybara-github · commit fe9e9e04cbc7 · 2023-12-13T22:10:12.000-08:00
After an action was executed remotely, RemoteSpawnRunner would use the timestamps in the execution metadata to record appropriate timing phases into the JSON profile. However, there are durations in-between the existing phases that are unaccounted for. Depending on the RBE server implemenation, these phases could mean different things: - Sandbox preparation - Cleaning up sandbox environments post-execution - Others Missing these durations inside the timing profile would cause confusion to end users as it would be interpreted as nothing happened in between the existing phases. Add these durations into the profile as "pre-X" phases so that user is aware of activities could still be happening during that time. RBE server implementation should be able to alter these label programmatically if necessary. Closes #20387. PiperOrigin-RevId: 590816782 Change-Id: I2bee36be928db24a14fab18bc519c3893723b7d6
diff --git a/src/main/java/com/google/devtools/build/lib/remote/RemoteSpawnRunner.java b/src/main/java/com/google/devtools/build/lib/remote/RemoteSpawnRunner.java
@@ -15,6 +15,7 @@
 package com.google.devtools.build.lib.remote;
 
 import static com.google.common.base.Preconditions.checkNotNull;
+import static com.google.devtools.build.lib.profiler.ProfilerTask.FETCH;
 import static com.google.devtools.build.lib.profiler.ProfilerTask.REMOTE_DOWNLOAD;
 import static com.google.devtools.build.lib.profiler.ProfilerTask.REMOTE_EXECUTION;
 import static com.google.devtools.build.lib.profiler.ProfilerTask.REMOTE_PROCESS_TIME;
@@ -341,16 +342,34 @@ private static void profileAccounting(ExecutedActionMetadata executedActionMetad
         "queue");
     logProfileTask(
         converter,
+        executedActionMetadata.getWorkerStartTimestamp(),
         executedActionMetadata.getInputFetchStartTimestamp(),
-        executedActionMetadata.getInputFetchCompletedTimestamp(),
         REMOTE_SETUP,
+        "pre-fetch");
+    logProfileTask(
+        converter,
+        executedActionMetadata.getInputFetchStartTimestamp(),
+        executedActionMetadata.getInputFetchCompletedTimestamp(),
+        FETCH,
         "fetch");
+    logProfileTask(
+        converter,
+        executedActionMetadata.getInputFetchCompletedTimestamp(),
+        executedActionMetadata.getExecutionStartTimestamp(),
+        REMOTE_SETUP,
+        "pre-execute");
     logProfileTask(
         converter,
         executedActionMetadata.getExecutionStartTimestamp(),
         executedActionMetadata.getExecutionCompletedTimestamp(),
         REMOTE_PROCESS_TIME,
         "execute");
+    logProfileTask(
+        converter,
+        executedActionMetadata.getExecutionCompletedTimestamp(),
+        executedActionMetadata.getOutputUploadStartTimestamp(),
+        REMOTE_SETUP,
+        "pre-upload");
     logProfileTask(
         converter,
         executedActionMetadata.getOutputUploadStartTimestamp(),
