Skip to content

Commit 394ddb8

Browse files
tjgqcopybara-github
tjgq
authored and
copybara-github
committed
Record additional profiling information for remotely executed actions.
Closes bazelbuild#15348. PiperOrigin-RevId: 445882024
1 parent d27be97 commit 394ddb8

3 files changed

Lines changed: 91 additions & 23 deletions

File tree

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

Lines changed: 40 additions & 23 deletions
Original file line numberDiff line numberDiff line change
@@ -19,28 +19,28 @@
1919
import java.util.concurrent.TimeUnit;
2020

2121
/**
22-
* Provides the clock implementation used by Blaze, which is {@link JavaClock}
23-
* by default, but can be overridden at runtime. Note that if you set this
24-
* clock, you also have to set the clock used by the Profiler.
22+
* Provides the clock implementation used by Blaze, which is {@link JavaClock} by default, but can
23+
* be overridden at runtime. If you set this clock, you also have to set the clock used by the
24+
* Profiler.
25+
*
26+
* <p>Note that clock readings are relative to an unspecified reference time, so returned values are
27+
* only meaningful when compared to each other. A {@link NanosToMillisSinceEpochConverter} or {@link
28+
* MillisSinceEpochToNanosConverter} may be used to convert clock readings into milliseconds since
29+
* the epoch or vice-versa.
2530
*/
2631
@ThreadSafe
2732
public abstract class BlazeClock {
2833

29-
private BlazeClock() {
30-
}
34+
private BlazeClock() {}
3135

3236
private static volatile Clock instance = new JavaClock();
3337

34-
/**
35-
* Returns singleton instance of the clock
36-
*/
38+
/** Returns singleton instance of the clock */
3739
public static Clock instance() {
3840
return instance;
3941
}
4042

41-
/**
42-
* Overrides default clock instance.
43-
*/
43+
/** Overrides default clock instance. */
4444
public static synchronized void setClock(Clock clock) {
4545
instance = clock;
4646
}
@@ -49,34 +49,51 @@ public static long nanoTime() {
4949
return instance().nanoTime();
5050
}
5151

52-
/**
53-
* Converts from nanos to millis since the epoch. In particular, note that {@link System#nanoTime}
54-
* does not specify any particular time reference but only notes that returned values are only
55-
* meaningful when taking in relation to each other.
56-
*/
52+
/** Converts from nanos to millis since the epoch. */
5753
public interface NanosToMillisSinceEpochConverter {
54+
5855
/** Converts from nanos to millis since the epoch. */
5956
long toEpochMillis(long timeNanos);
6057
}
6158

6259
/**
63-
* Creates a {@link NanosToMillisSinceEpochConverter} from the current BlazeClock instance by
64-
* taking the current time in millis and the current time in nanos to compute the appropriate
65-
* offset.
60+
* Creates a {@link NanosToMillisSinceEpochConverter} from the current {@link BlazeClock}
61+
* instance.
6662
*/
6763
public static NanosToMillisSinceEpochConverter createNanosToMillisSinceEpochConverter() {
6864
return createNanosToMillisSinceEpochConverter(instance);
6965
}
7066

67+
/** Creates a {@link NanosToMillisSinceEpochConverter} from the given {@link Clock}. */
68+
@VisibleForTesting
69+
public static NanosToMillisSinceEpochConverter createNanosToMillisSinceEpochConverter(
70+
Clock clock) {
71+
long nowInMillis = clock.currentTimeMillis();
72+
long nowInNanos = clock.nanoTime();
73+
return (timeNanos) -> nowInMillis - TimeUnit.NANOSECONDS.toMillis(nowInNanos - timeNanos);
74+
}
75+
76+
/** Converts from millis since the epoch to nanos. */
77+
public interface MillisSinceEpochToNanosConverter {
78+
79+
/** Converts from millis since the epoch to nanos. */
80+
long toNanos(long timeMillis);
81+
}
82+
7183
/**
72-
* Creates a {@link NanosToMillisSinceEpochConverter} from clock by taking the current time in
73-
* millis and the current time in nanos to compute the appropriate offset.
84+
* Creates a {@link NanosToMillisSinceEpochConverter} from the current {@link BlazeClock}
85+
* instance.
7486
*/
87+
public static MillisSinceEpochToNanosConverter createMillisSinceEpochToNanosConverter() {
88+
return createMillisSinceEpochToNanosConverter(instance);
89+
}
90+
91+
/** Creates a {@link MillisSinceEpochToNanosConverter} from the given {@link Clock}. */
7592
@VisibleForTesting
76-
public static NanosToMillisSinceEpochConverter createNanosToMillisSinceEpochConverter(
93+
public static MillisSinceEpochToNanosConverter createMillisSinceEpochToNanosConverter(
7794
Clock clock) {
7895
long nowInMillis = clock.currentTimeMillis();
7996
long nowInNanos = clock.nanoTime();
80-
return (timeNanos) -> nowInMillis - TimeUnit.NANOSECONDS.toMillis((nowInNanos - timeNanos));
97+
return (timeMillis) -> nowInNanos - TimeUnit.MILLISECONDS.toNanos(nowInMillis - timeMillis);
8198
}
8299
}

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

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -59,6 +59,7 @@ java_library(
5959
"//src/main/java/com/google/devtools/build/lib/authandtls",
6060
"//src/main/java/com/google/devtools/build/lib/bazel/repository/downloader",
6161
"//src/main/java/com/google/devtools/build/lib/buildeventstream",
62+
"//src/main/java/com/google/devtools/build/lib/clock",
6263
"//src/main/java/com/google/devtools/build/lib/collect/nestedset",
6364
"//src/main/java/com/google/devtools/build/lib/concurrent",
6465
"//src/main/java/com/google/devtools/build/lib/events",

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

Lines changed: 50 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -15,8 +15,11 @@
1515
package com.google.devtools.build.lib.remote;
1616

1717
import static com.google.common.base.Preconditions.checkNotNull;
18+
import static com.google.devtools.build.lib.profiler.ProfilerTask.PROCESS_TIME;
1819
import static com.google.devtools.build.lib.profiler.ProfilerTask.REMOTE_DOWNLOAD;
1920
import static com.google.devtools.build.lib.profiler.ProfilerTask.REMOTE_EXECUTION;
21+
import static com.google.devtools.build.lib.profiler.ProfilerTask.REMOTE_QUEUE;
22+
import static com.google.devtools.build.lib.profiler.ProfilerTask.REMOTE_SETUP;
2023
import static com.google.devtools.build.lib.profiler.ProfilerTask.UPLOAD_TIME;
2124
import static com.google.devtools.build.lib.remote.util.Utils.createSpawnResult;
2225

@@ -38,6 +41,8 @@
3841
import com.google.devtools.build.lib.actions.SpawnResult;
3942
import com.google.devtools.build.lib.actions.SpawnResult.Status;
4043
import com.google.devtools.build.lib.actions.cache.VirtualActionInput;
44+
import com.google.devtools.build.lib.clock.BlazeClock;
45+
import com.google.devtools.build.lib.clock.BlazeClock.MillisSinceEpochToNanosConverter;
4146
import com.google.devtools.build.lib.concurrent.ThreadSafety.ThreadSafe;
4247
import com.google.devtools.build.lib.events.Event;
4348
import com.google.devtools.build.lib.events.Reporter;
@@ -273,6 +278,7 @@ public SpawnResult exec(Spawn spawn, SpawnExecutionContext context)
273278
outErr.printErr(message + "\n");
274279
}
275280

281+
profileAccounting(result.getExecutionMetadata());
276282
spawnMetricsAccounting(spawnMetrics, result.getExecutionMetadata());
277283

278284
try (SilentCloseable c = prof.profile(REMOTE_DOWNLOAD, "download server logs")) {
@@ -303,6 +309,50 @@ public SpawnResult exec(Spawn spawn, SpawnExecutionContext context)
303309
}
304310
}
305311

312+
private static void profileAccounting(ExecutedActionMetadata executedActionMetadata) {
313+
MillisSinceEpochToNanosConverter converter =
314+
BlazeClock.createMillisSinceEpochToNanosConverter();
315+
316+
logProfileTask(
317+
converter,
318+
executedActionMetadata.getQueuedTimestamp(),
319+
executedActionMetadata.getWorkerStartTimestamp(),
320+
REMOTE_QUEUE,
321+
"queue");
322+
logProfileTask(
323+
converter,
324+
executedActionMetadata.getInputFetchStartTimestamp(),
325+
executedActionMetadata.getInputFetchCompletedTimestamp(),
326+
REMOTE_SETUP,
327+
"fetch");
328+
logProfileTask(
329+
converter,
330+
executedActionMetadata.getExecutionStartTimestamp(),
331+
executedActionMetadata.getExecutionCompletedTimestamp(),
332+
PROCESS_TIME,
333+
"execute");
334+
logProfileTask(
335+
converter,
336+
executedActionMetadata.getOutputUploadStartTimestamp(),
337+
executedActionMetadata.getOutputUploadCompletedTimestamp(),
338+
UPLOAD_TIME,
339+
"upload");
340+
}
341+
342+
private static void logProfileTask(
343+
MillisSinceEpochToNanosConverter converter,
344+
Timestamp start,
345+
Timestamp end,
346+
ProfilerTask type,
347+
String description) {
348+
Profiler.instance()
349+
.logSimpleTask(
350+
converter.toNanos(Timestamps.toMillis(start)),
351+
converter.toNanos(Timestamps.toMillis(end)),
352+
type,
353+
description);
354+
}
355+
306356
/** conversion utility for protobuf Timestamp difference to java.time.Duration */
307357
private static Duration between(Timestamp from, Timestamp to) {
308358
return Duration.ofNanos(Durations.toNanos(Timestamps.between(from, to)));

0 commit comments

Comments
 (0)