Skip to content

Commit

Permalink
Record additional profiling information for remotely executed actions. (
Browse files Browse the repository at this point in the history
bazelbuild#15443)

Closes bazelbuild#15348.

PiperOrigin-RevId: 445882024

Co-authored-by: Tiago Quelhas <tjgq@google.com>
  • Loading branch information
2 people authored and meteorcloudy committed May 10, 2022
1 parent 6b293f4 commit a430042
Show file tree
Hide file tree
Showing 3 changed files with 91 additions and 23 deletions.
63 changes: 40 additions & 23 deletions src/main/java/com/google/devtools/build/lib/clock/BlazeClock.java
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}
Expand All @@ -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);
}
}
1 change: 1 addition & 0 deletions src/main/java/com/google/devtools/build/lib/remote/BUILD
Original file line number Diff line number Diff line change
Expand Up @@ -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",
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;

Expand All @@ -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;
Expand Down Expand Up @@ -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")) {
Expand Down Expand Up @@ -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)));
Expand Down

0 comments on commit a430042

Please sign in to comment.