Record additional profiling information for remotely executed actions.

src/main/java/com/google/devtools/build/lib/clock/BlazeClock.java

@@ -19,28 +19,28 @@
 import java.util.concurrent.TimeUnit;
 
 /**
- * Provides the clock implementation used by Blaze, which is {@link JavaClock}
- * by default, but can be overridden at runtime. Note that if you set this
- * clock, you also have to set the clock used by the Profiler.
+ * Provides the clock implementation used by Blaze, which is {@link JavaClock} by default, but can
+ * be overridden at runtime. If you set this clock, you also have to set the clock used by the
+ * Profiler.
+ *
+ * <p>Note that clock readings are relative to an unspecified reference time, so returned values are
+ * only meaningful when compared to each other. A {@link NanosToMillisSinceEpochConverter} or {@link
+ * MillisSinceEpochToNanosConverter} may be used to convert clock readings into milliseconds since
+ * the epoch or vice-versa.
  */
 @ThreadSafe
 public abstract class BlazeClock {
 
-  private BlazeClock() {
-  }
+  private BlazeClock() {}
 
   private static volatile Clock instance = new JavaClock();
 
-  /**
-   * Returns singleton instance of the clock
-   */
+  /** Returns singleton instance of the clock */
   public static Clock instance() {
     return instance;
   }
 
-  /**
-   * Overrides default clock instance.
-   */
+  /** Overrides default clock instance. */
   public static synchronized void setClock(Clock clock) {
     instance = clock;
   }
@@ -49,34 +49,51 @@ public static long nanoTime() {
     return instance().nanoTime();
   }
 
-  /**
-   * Converts from nanos to millis since the epoch. In particular, note that {@link System#nanoTime}
-   * does not specify any particular time reference but only notes that returned values are only
-   * meaningful when taking in relation to each other.
-   */
+  /** Converts from nanos to millis since the epoch. */
   public interface NanosToMillisSinceEpochConverter {
+
     /** Converts from nanos to millis since the epoch. */
     long toEpochMillis(long timeNanos);
   }
 
   /**
-   * Creates a {@link NanosToMillisSinceEpochConverter} from the current BlazeClock instance by
-   * taking the current time in millis and the current time in nanos to compute the appropriate
-   * offset.
+   * Creates a {@link NanosToMillisSinceEpochConverter} from the current {@link BlazeClock}
+   * instance.
    */
   public static NanosToMillisSinceEpochConverter createNanosToMillisSinceEpochConverter() {
     return createNanosToMillisSinceEpochConverter(instance);
   }
 
+  /** Creates a {@link NanosToMillisSinceEpochConverter} from the given {@link Clock}. */
+  @VisibleForTesting
+  public static NanosToMillisSinceEpochConverter createNanosToMillisSinceEpochConverter(
+      Clock clock) {
+    long nowInMillis = clock.currentTimeMillis();
+    long nowInNanos = clock.nanoTime();
+    return (timeNanos) -> nowInMillis - TimeUnit.NANOSECONDS.toMillis(nowInNanos - timeNanos);
+  }
+
+  /** Converts from millis since the epoch to nanos. */
+  public interface MillisSinceEpochToNanosConverter {
+
+    /** Converts from millis since the epoch to nanos. */
+    long toNanos(long timeMillis);
+  }
+
   /**
-   * Creates a {@link NanosToMillisSinceEpochConverter} from clock by taking the current time in
-   * millis and the current time in nanos to compute the appropriate offset.
+   * Creates a {@link NanosToMillisSinceEpochConverter} from the current {@link BlazeClock}
+   * instance.
    */
+  public static MillisSinceEpochToNanosConverter createMillisSinceEpochToNanosConverter() {
+    return createMillisSinceEpochToNanosConverter(instance);
+  }
+
+  /** Creates a {@link MillisSinceEpochToNanosConverter} from the given {@link Clock}. */
   @VisibleForTesting
-  public static NanosToMillisSinceEpochConverter createNanosToMillisSinceEpochConverter(
+  public static MillisSinceEpochToNanosConverter createMillisSinceEpochToNanosConverter(
       Clock clock) {
     long nowInMillis = clock.currentTimeMillis();
     long nowInNanos = clock.nanoTime();
-    return (timeNanos) -> nowInMillis - TimeUnit.NANOSECONDS.toMillis((nowInNanos - timeNanos));
+    return (timeMillis) -> nowInNanos - TimeUnit.MILLISECONDS.toNanos(nowInMillis - timeMillis);
   }
 }

src/main/java/com/google/devtools/build/lib/remote/BUILD

@@ -59,6 +59,7 @@ java_library(
         "//src/main/java/com/google/devtools/build/lib/authandtls",
         "//src/main/java/com/google/devtools/build/lib/bazel/repository/downloader",
         "//src/main/java/com/google/devtools/build/lib/buildeventstream",
+        "//src/main/java/com/google/devtools/build/lib/clock",
         "//src/main/java/com/google/devtools/build/lib/collect/nestedset",
         "//src/main/java/com/google/devtools/build/lib/concurrent",
         "//src/main/java/com/google/devtools/build/lib/events",

src/main/java/com/google/devtools/build/lib/remote/RemoteSpawnRunner.java

@@ -15,8 +15,12 @@
 package com.google.devtools.build.lib.remote;
 
 import static com.google.common.base.Preconditions.checkNotNull;
+import static com.google.devtools.build.lib.clock.BlazeClock.MillisSinceEpochToNanosConverter;
+import static com.google.devtools.build.lib.profiler.ProfilerTask.PROCESS_TIME;
 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_QUEUE;
+import static com.google.devtools.build.lib.profiler.ProfilerTask.REMOTE_SETUP;
 import static com.google.devtools.build.lib.profiler.ProfilerTask.UPLOAD_TIME;
 import static com.google.devtools.build.lib.remote.util.Utils.createSpawnResult;
 
@@ -38,6 +42,7 @@
 import com.google.devtools.build.lib.actions.SpawnResult;
 import com.google.devtools.build.lib.actions.SpawnResult.Status;
 import com.google.devtools.build.lib.actions.cache.VirtualActionInput;
+import com.google.devtools.build.lib.clock.BlazeClock;
 import com.google.devtools.build.lib.concurrent.ThreadSafety.ThreadSafe;
 import com.google.devtools.build.lib.events.Event;
 import com.google.devtools.build.lib.events.Reporter;
@@ -273,6 +278,7 @@ public SpawnResult exec(Spawn spawn, SpawnExecutionContext context)
               outErr.printErr(message + "\n");
             }
 
+            profileAccounting(result.getExecutionMetadata());
             spawnMetricsAccounting(spawnMetrics, result.getExecutionMetadata());
 
             try (SilentCloseable c = prof.profile(REMOTE_DOWNLOAD, "download server logs")) {
@@ -303,7 +309,47 @@ public SpawnResult exec(Spawn spawn, SpawnExecutionContext context)
     }
   }
 
-  /** conversion utility for protobuf Timestamp difference to java.time.Duration */
+  private static void profileAccounting(ExecutedActionMetadata executedActionMetadata) {
+    MillisSinceEpochToNanosConverter converter =
+        BlazeClock.createMillisSinceEpochToNanosConverter();
+
+    logProfileTask(
+        converter,
+        executedActionMetadata.getQueuedTimestamp(),
+        executedActionMetadata.getWorkerStartTimestamp(),
+        REMOTE_QUEUE,
+        "queue");
+    logProfileTask(
+        converter,
+        executedActionMetadata.getInputFetchStartTimestamp(),
+        executedActionMetadata.getInputFetchCompletedTimestamp(),
+        REMOTE_SETUP,
+        "fetch");
+    logProfileTask(
+        converter,
+        executedActionMetadata.getExecutionStartTimestamp(),
+        executedActionMetadata.getExecutionCompletedTimestamp(),
+        PROCESS_TIME,
+        "execute");
+    logProfileTask(
+        converter,
+        executedActionMetadata.getOutputUploadStartTimestamp(),
+        executedActionMetadata.getOutputUploadCompletedTimestamp(),
+        UPLOAD_TIME,
+        "upload");
+  }
+
+  private static void logProfileTask(MillisSinceEpochToNanosConverter converter, Timestamp start,
+      Timestamp end, ProfilerTask type, String description) {
+    Profiler.instance().logSimpleTask(
+        converter.toNanos(Timestamps.toMillis(start)),
+        converter.toNanos(Timestamps.toMillis(end)),
+        type, description);
+  }
+
+  /**
+   * conversion utility for protobuf Timestamp difference to java.time.Duration
+   */
   private static Duration between(Timestamp from, Timestamp to) {
     return Duration.ofNanos(Durations.toNanos(Timestamps.between(from, to)));
   }