diff --git a/src/main/java/com/google/devtools/build/lib/actions/SpawnMetrics.java b/src/main/java/com/google/devtools/build/lib/actions/SpawnMetrics.java index 5fa2d8ef43f200..933efc1f313002 100644 --- a/src/main/java/com/google/devtools/build/lib/actions/SpawnMetrics.java +++ b/src/main/java/com/google/devtools/build/lib/actions/SpawnMetrics.java @@ -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; diff --git a/src/main/java/com/google/devtools/build/lib/exec/local/LocalSpawnRunner.java b/src/main/java/com/google/devtools/build/lib/exec/local/LocalSpawnRunner.java index 0b9db5602e8417..2dc57b1a1cb612 100644 --- a/src/main/java/com/google/devtools/build/lib/exec/local/LocalSpawnRunner.java +++ b/src/main/java/com/google/devtools/build/lib/exec/local/LocalSpawnRunner.java @@ -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; @@ -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; @@ -124,18 +126,24 @@ 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, @@ -143,11 +151,12 @@ public SpawnResult exec(Spawn spawn, SpawnExecutionContext context) 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(); } } } @@ -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; @@ -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); } @@ -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 @@ -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(); } @@ -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; @@ -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() @@ -420,18 +443,20 @@ 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)); @@ -439,13 +464,7 @@ private SpawnResult start() 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)); } @@ -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