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. + * + *

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 18147bf519a1e6..849e4c23fb0f53 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 c8e6fecaade50a..d3f0c008726ff6 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; @@ -274,6 +279,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")) { @@ -304,6 +310,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)));