diff --git a/src/main/java/com/google/devtools/build/lib/clock/BlazeClock.java b/src/main/java/com/google/devtools/build/lib/clock/BlazeClock.java
index ebea140348c785..fd46e47c10389d 100644
--- a/src/main/java/com/google/devtools/build/lib/clock/BlazeClock.java
+++ b/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);
}
}
diff --git a/src/main/java/com/google/devtools/build/lib/remote/BUILD b/src/main/java/com/google/devtools/build/lib/remote/BUILD
index fb95aa355758be..3356a6c1cb28eb 100644
--- a/src/main/java/com/google/devtools/build/lib/remote/BUILD
+++ b/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",
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
index 07a11923f0f5d8..a74d6ac9db0c56 100644
--- 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,8 +15,11 @@
package com.google.devtools.build.lib.remote;
import static com.google.common.base.Preconditions.checkNotNull;
+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 +41,8 @@
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.clock.BlazeClock.MillisSinceEpochToNanosConverter;
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,6 +309,50 @@ public SpawnResult exec(Spawn spawn, SpawnExecutionContext context)
}
}
+ 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)));