Skip to content

Commit

Permalink
Add SpawnMetrics for LocalSpawnRunner
Browse files Browse the repository at this point in the history 
PiperOrigin-RevId: 408846457
  • Loading branch information
@copybara-github
wilwell authored and copybara-github committed Nov 10, 2021
1 parent 27f1dbd commit 7199824
Show file tree
Hide file tree
Showing 2 changed files with 43 additions and 17 deletions.
5 changes: 5 additions & 0 deletions src/main/java/com/google/devtools/build/lib/actions/SpawnMetrics.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -340,6 +340,11 @@ public Builder setSetupTime(Duration setupTime) {
return this;
}

public Builder addSetupTime(Duration setupTime) {
this.setupTime = this.setupTime.plus(setupTime);
return this;
}

public Builder setUploadTime(Duration uploadTime) {
this.uploadTime = uploadTime;
return this;
Expand Down
55 changes: 38 additions & 17 deletions src/main/java/com/google/devtools/build/lib/exec/local/LocalSpawnRunner.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,7 @@

import com.google.common.base.Joiner;
import com.google.common.base.Preconditions;
import com.google.common.base.Stopwatch;
import com.google.common.collect.ImmutableList;
import com.google.common.collect.ImmutableMap;
import com.google.common.flogger.GoogleLogger;
Expand All @@ -32,6 +33,7 @@
import com.google.devtools.build.lib.actions.ResourceManager.ResourceHandle;
import com.google.devtools.build.lib.actions.ResourceManager.ResourcePriority;
import com.google.devtools.build.lib.actions.Spawn;
import com.google.devtools.build.lib.actions.SpawnMetrics;
import com.google.devtools.build.lib.actions.SpawnResult;
import com.google.devtools.build.lib.actions.SpawnResult.Status;
import com.google.devtools.build.lib.actions.Spawns;
Expand Down Expand Up @@ -124,30 +126,37 @@ public String getName() {
public SpawnResult exec(Spawn spawn, SpawnExecutionContext context)
throws IOException, InterruptedException, ExecException, ForbiddenActionInputException {

SpawnMetrics.Builder spawnMetrics = SpawnMetrics.Builder.forLocalExec();
Stopwatch totalTimeStopwatch = Stopwatch.createStarted();
Stopwatch setupTimeStopwatch = Stopwatch.createStarted();
runfilesTreeUpdater.updateRunfilesDirectory(
execRoot,
spawn.getRunfilesSupplier(),
binTools,
spawn.getEnvironment(),
context.getFileOutErr());
spawnMetrics.addSetupTime(setupTimeStopwatch.elapsed());

try (SilentCloseable c =
Profiler.instance()
.profile(ProfilerTask.LOCAL_EXECUTION, spawn.getResourceOwner().getMnemonic())) {
ActionExecutionMetadata owner = spawn.getResourceOwner();
context.report(SpawnSchedulingEvent.create(getName()));

Stopwatch queueStopwatch = Stopwatch.createStarted();
try (ResourceHandle handle =
resourceManager.acquireResources(
owner,
spawn.getLocalResources(),
context.speculating()
? ResourcePriority.DYNAMIC_STANDALONE
: ResourcePriority.LOCAL)) {
spawnMetrics.setQueueTime(queueStopwatch.elapsed());
context.report(SpawnExecutingEvent.create(getName()));
if (!localExecutionOptions.localLockfreeOutput) {
context.lockOutputFiles();
}
return new SubprocessHandler(spawn, context).run();
return new SubprocessHandler(spawn, context, spawnMetrics, totalTimeStopwatch).run();
}
}
}
Expand All @@ -173,6 +182,8 @@ protected Path createActionTemp(Path execRoot) throws IOException {
private final class SubprocessHandler {
private final Spawn spawn;
private final SpawnExecutionContext context;
private final SpawnMetrics.Builder spawnMetrics;
private final Stopwatch totalTimeStopwatch;

private final long creationTime = System.currentTimeMillis();
private long stateStartTime = creationTime;
Expand All @@ -187,10 +198,16 @@ private final class SubprocessHandler {

private final int id;

public SubprocessHandler(Spawn spawn, SpawnExecutionContext context) {
public SubprocessHandler(
Spawn spawn,
SpawnExecutionContext context,
SpawnMetrics.Builder spawnMetrics,
Stopwatch totalTimeStopwatch) {
Preconditions.checkArgument(!spawn.getArguments().isEmpty());
this.spawn = spawn;
this.totalTimeStopwatch = totalTimeStopwatch;
this.context = context;
this.spawnMetrics = spawnMetrics;
this.id = context.getId();
setState(State.PARSING);
}
Expand Down Expand Up @@ -293,6 +310,9 @@ private SpawnResult start()
throws InterruptedException, IOException, ForbiddenActionInputException {
logger.atInfo().log("starting local subprocess #%d, argv: %s", id, debugCmdString());

SpawnResult.Builder spawnResultBuilder =
new SpawnResult.Builder().setRunnerName(getName()).setExecutorHostname(hostName);

FileOutErr outErr = context.getFileOutErr();
String actionType = spawn.getResourceOwner().getMnemonic();
if (localExecutionOptions.allowedLocalAction != null
Expand All @@ -311,13 +331,13 @@ private SpawnResult start()
+ localExecutionOptions.allowedLocalAction.regexPattern()
+ "\n")
.getBytes(UTF_8));
return new SpawnResult.Builder()
.setRunnerName(getName())
spawnMetrics.setTotalTime(totalTimeStopwatch.elapsed());
return spawnResultBuilder
.setStatus(Status.EXECUTION_DENIED)
.setExitCode(LOCAL_EXEC_ERROR)
.setExecutorHostname(hostName)
.setFailureDetail(
makeFailureDetail(LOCAL_EXEC_ERROR, Status.EXECUTION_DENIED, actionType))
.setSpawnMetrics(spawnMetrics.build())
.build();
}

Expand All @@ -327,6 +347,8 @@ private SpawnResult start()
context.prefetchInputs();
}

spawnMetrics.setInputFiles(spawn.getInputFiles().memoizedFlattenAndGetSize());
Stopwatch setupTimeStopwatch = Stopwatch.createStarted();
for (ActionInput input : spawn.getInputFiles().toList()) {
if (input instanceof VirtualActionInput) {
VirtualActionInput virtualActionInput = (VirtualActionInput) input;
Expand Down Expand Up @@ -389,8 +411,9 @@ private SpawnResult start()
args = ImmutableList.copyOf(newArgs);
}
subprocessBuilder.setArgv(args);
spawnMetrics.addSetupTime(setupTimeStopwatch.elapsed());

long startTime = System.currentTimeMillis();
Stopwatch executionStopwatch = Stopwatch.createStarted();
TerminationStatus terminationStatus;
try (SilentCloseable c =
Profiler.instance()
Expand Down Expand Up @@ -420,32 +443,28 @@ private SpawnResult start()
.write(
("Action failed to execute: java.io.IOException: " + msg + "\n").getBytes(UTF_8));
outErr.getErrorStream().flush();
return new SpawnResult.Builder()
.setRunnerName(getName())
spawnMetrics.setTotalTime(totalTimeStopwatch.elapsed());
return spawnResultBuilder
.setStatus(Status.EXECUTION_FAILED)
.setExitCode(LOCAL_EXEC_ERROR)
.setExecutorHostname(hostName)
.setFailureDetail(
makeFailureDetail(LOCAL_EXEC_ERROR, Status.EXECUTION_FAILED, actionType))
.setSpawnMetrics(spawnMetrics.build())
.build();
}
setState(State.SUCCESS);
// TODO(b/62588075): Calculate wall time inside commands instead?
Duration wallTime = Duration.ofMillis(System.currentTimeMillis() - startTime);
Duration wallTime = executionStopwatch.elapsed();
spawnMetrics.setExecutionWallTime(wallTime);

boolean wasTimeout =
terminationStatus.timedOut()
|| (processWrapper != null && wasTimeout(context.getTimeout(), wallTime));
int exitCode =
wasTimeout ? SpawnResult.POSIX_TIMEOUT_EXIT_CODE : terminationStatus.getRawExitCode();
Status status =
wasTimeout ? Status.TIMEOUT : (exitCode == 0 ? Status.SUCCESS : Status.NON_ZERO_EXIT);
SpawnResult.Builder spawnResultBuilder =
new SpawnResult.Builder()
.setRunnerName(getName())
.setStatus(status)
.setExitCode(exitCode)
.setExecutorHostname(hostName)
.setWallTime(wallTime);
spawnResultBuilder.setStatus(status).setExitCode(exitCode).setWallTime(wallTime);
if (status != Status.SUCCESS) {
spawnResultBuilder.setFailureDetail(makeFailureDetail(exitCode, status, actionType));
}
Expand All @@ -471,6 +490,8 @@ private SpawnResult start()
}
});
}
spawnMetrics.setTotalTime(totalTimeStopwatch.elapsed());
spawnResultBuilder.setSpawnMetrics(spawnMetrics.build());
return spawnResultBuilder.build();
} finally {
// Delete the temp directory tree, so the next action that this thread executes will get a
Expand Down

0 comments on commit 7199824

Please sign in to comment.