Report ActionExecuted.start_time and ActionExecuted.end_time.

By populating these fields for all actions we achieve the minimal goals of
issue bazelbuild#19471 and make action timing information available. No strategy-specific
information is reported. Uses the earliest `SpawnResult.getStartTime()` to
determine the start_time to report. Uses `SpawnResult.getWallTimeInMs()` to
compute the action's end-time.

PiperOrigin-RevId: 576511612
Change-Id: Ia41de12ca8ddfab315ee224c32ed78c674daea63

src/main/java/com/google/devtools/build/lib/actions/ActionExecutedEvent.java

@@ -14,6 +14,8 @@
 
 package com.google.devtools.build.lib.actions;
 
+import static com.google.common.base.Preconditions.checkNotNull;
+
 import com.google.common.base.MoreObjects;
 import com.google.common.base.Preconditions;
 import com.google.common.collect.ImmutableList;
@@ -32,6 +34,8 @@
 import com.google.devtools.build.lib.server.FailureDetails;
 import com.google.devtools.build.lib.vfs.Path;
 import com.google.devtools.build.lib.vfs.PathFragment;
+import com.google.protobuf.Timestamp;
+import java.time.Instant;
 import java.util.Collection;
 import javax.annotation.Nullable;
 
@@ -53,6 +57,12 @@ public final class ActionExecutedEvent implements BuildEventWithConfiguration {
   private final ImmutableList<MetadataLog> actionMetadataLogs;
   private final ErrorTiming timing;
 
+  /** Timestamp of the action starting; if no timestamp is available will be {@code null}. */
+  @Nullable private final Instant startTime;
+
+  /** Timestamp of the action finishing; if no timestamp is available will be {@code null}. */
+  @Nullable private final Instant endTime;
+
   public ActionExecutedEvent(
       PathFragment actionId,
       Action action,
@@ -63,7 +73,9 @@ public ActionExecutedEvent(
       Path stdout,
       Path stderr,
       ImmutableList<MetadataLog> actionMetadataLogs,
-      ErrorTiming timing) {
+      ErrorTiming timing,
+      @Nullable Instant startTime,
+      @Nullable Instant endTime) {
     this.actionId = actionId;
     this.action = action;
     this.exception = exception;
@@ -73,8 +85,9 @@ public ActionExecutedEvent(
     this.stdout = stdout;
     this.stderr = stderr;
     this.timing = timing;
-    this.actionMetadataLogs = actionMetadataLogs;
-    Preconditions.checkNotNull(this.actionMetadataLogs, this);
+    this.actionMetadataLogs = checkNotNull(actionMetadataLogs, this);
+    this.startTime = startTime;
+    this.endTime = endTime;
     Preconditions.checkState(
         (this.exception == null) == (this.timing == ErrorTiming.NO_ERROR), this);
     Preconditions.checkState(
@@ -188,6 +201,12 @@ public BuildEventStreamProtos.BuildEvent asStreamProto(BuildEventContext convert
         BuildEventStreamProtos.ActionExecuted.newBuilder()
             .setSuccess(getException() == null)
             .setType(action.getMnemonic());
+    if (startTime != null) {
+      actionBuilder.setStartTime(timestampProto(startTime));
+      if (endTime != null) {
+        actionBuilder.setEndTime(timestampProto(endTime));
+      }
+    }
 
     if (exception != null) {
       // TODO(b/150405553): This statement seems to be confused. The exit_code field of
@@ -264,6 +283,8 @@ public String toString() {
         .add("primaryOutput", primaryOutput)
         .add("outputArtifact", outputArtifact)
         .add("primaryOutputMetadata", primaryOutputMetadata)
+        .add("startTime", startTime)
+        .add("endTime", endTime)
         .toString();
   }
 
@@ -273,4 +294,11 @@ public enum ErrorTiming {
     BEFORE_EXECUTION,
     AFTER_EXECUTION
   }
+
+  private static Timestamp timestampProto(Instant time) {
+    return Timestamp.newBuilder()
+        .setSeconds(time.getEpochSecond())
+        .setNanos(time.getNano())
+        .build();
+  }
 }

src/main/java/com/google/devtools/build/lib/actions/ActionExecutionException.java

@@ -143,7 +143,6 @@ public static ActionExecutionException fromExecException(
 
     DetailedExitCode code =
         DetailedExitCode.of(exception.getFailureDetail(action.describe() + " failed: " + message));
-
     if (exception instanceof LostInputsExecException) {
       return ((LostInputsExecException) exception).fromExecException(message, action, code);
     }

src/main/java/com/google/devtools/build/lib/actions/BUILD

@@ -125,6 +125,7 @@ java_library(
         "SimpleSpawn.java",
         "SingleStringArgFormatter.java",
         "Spawn.java",
+        "SpawnActionExecutionException.java",
         "SpawnExecutedEvent.java",
         "SpawnMetrics.java",
         "SpawnResult.java",

src/main/java/com/google/devtools/build/lib/actions/SpawnActionExecutionException.java

@@ -0,0 +1,38 @@
+// Copyright 2023 The Bazel Authors. All rights reserved.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//    http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package com.google.devtools.build.lib.actions;
+
+import com.google.devtools.build.lib.util.DetailedExitCode;
+
+/** An action failed to execute due to a failure in a Spawn. */
+public class SpawnActionExecutionException extends ActionExecutionException {
+
+  private final SpawnResult spawnResult;
+
+  public SpawnActionExecutionException(
+      ExecException e,
+      String message,
+      Action action,
+      DetailedExitCode code,
+      SpawnResult spawnResult) {
+    super(message, e, action, e.isCatastrophic(), code);
+    this.spawnResult = spawnResult;
+  }
+
+  /** Get the failed {@link SpawnResult} that led to this exception. */
+  public SpawnResult getSpawnResult() {
+    return spawnResult;
+  }
+}

src/main/java/com/google/devtools/build/lib/actions/SpawnResult.java

@@ -523,7 +523,6 @@ final class Builder {
 
     public SpawnResult build() {
       Preconditions.checkArgument(!runnerName.isEmpty());
-
       switch (status) {
         case SUCCESS:
           Preconditions.checkArgument(exitCode == 0, exitCode);

src/main/java/com/google/devtools/build/lib/analysis/BUILD

@@ -396,6 +396,7 @@ java_library(
         "//src/main/java/com/google/devtools/build/lib/events",
         "//src/main/java/com/google/devtools/build/lib/exec:bin_tools",
         "//src/main/java/com/google/devtools/build/lib/exec:execution_options",
+        "//src/main/java/com/google/devtools/build/lib/exec:spawn_exec_exception",
         "//src/main/java/com/google/devtools/build/lib/exec:spawn_strategy_resolver",
         "//src/main/java/com/google/devtools/build/lib/exec:streamed_test_output",
         "//src/main/java/com/google/devtools/build/lib/exec:test_log_helper",

src/main/java/com/google/devtools/build/lib/analysis/actions/SpawnAction.java

@@ -70,6 +70,7 @@
 import com.google.devtools.build.lib.collect.nestedset.NestedSet;
 import com.google.devtools.build.lib.collect.nestedset.NestedSetBuilder;
 import com.google.devtools.build.lib.concurrent.BlazeInterners;
+import com.google.devtools.build.lib.exec.SpawnExecException;
 import com.google.devtools.build.lib.exec.SpawnStrategyResolver;
 import com.google.devtools.build.lib.server.FailureDetails;
 import com.google.devtools.build.lib.server.FailureDetails.FailureDetail;
@@ -264,6 +265,9 @@ public final ActionResult execute(ActionExecutionContext actionExecutionContext)
     } catch (CommandLineExpansionException e) {
       throw createCommandLineException(e);
     } catch (ExecException e) {
+      if (e instanceof SpawnExecException) {
+        throw ((SpawnExecException) e).toActionExecutionException(this);
+      }
       throw ActionExecutionException.fromExecException(e, this);
     }
   }

src/main/java/com/google/devtools/build/lib/exec/BUILD

@@ -232,6 +232,7 @@ java_library(
     srcs = ["SpawnExecException.java"],
     deps = [
         "//src/main/java/com/google/devtools/build/lib/actions",
+        "//src/main/java/com/google/devtools/build/lib/util:detailed_exit_code",
         "//src/main/protobuf:failure_details_java_proto",
         "//third_party:guava",
     ],

src/main/java/com/google/devtools/build/lib/exec/SpawnExecException.java

@@ -17,10 +17,13 @@
 import static com.google.common.base.Preconditions.checkNotNull;
 
 import com.google.common.annotations.VisibleForTesting;
+import com.google.devtools.build.lib.actions.Action;
 import com.google.devtools.build.lib.actions.ExecException;
+import com.google.devtools.build.lib.actions.SpawnActionExecutionException;
 import com.google.devtools.build.lib.actions.SpawnResult;
 import com.google.devtools.build.lib.actions.SpawnResult.Status;
 import com.google.devtools.build.lib.server.FailureDetails.FailureDetail;
+import com.google.devtools.build.lib.util.DetailedExitCode;
 
 /**
  * A specialization of {@link ExecException} that indicates something went wrong when trying to
@@ -66,4 +69,11 @@ protected String getMessageForActionExecutionException() {
   protected FailureDetail getFailureDetail(String message) {
     return checkNotNull(result.failureDetail(), this);
   }
+
+  public SpawnActionExecutionException toActionExecutionException(Action action) {
+    String message = getMessageForActionExecutionException();
+    DetailedExitCode code =
+        DetailedExitCode.of(this.getFailureDetail(action.describe() + " failed: " + message));
+    return new SpawnActionExecutionException(this, message, action, code, getSpawnResult());
+  }
 }

src/main/java/com/google/devtools/build/lib/skyframe/SkyframeActionExecutor.java

@@ -16,7 +16,8 @@
 import static com.google.common.base.Preconditions.checkArgument;
 import static com.google.common.base.Preconditions.checkNotNull;
 import static com.google.common.base.Preconditions.checkState;
-import static com.google.common.collect.ImmutableList.toImmutableList;
+import static com.google.common.collect.Comparators.max;
+import static com.google.common.collect.Comparators.min;
 
 import com.google.common.collect.ImmutableList;
 import com.google.common.collect.ImmutableMap;
@@ -70,6 +71,7 @@
 import com.google.devtools.build.lib.actions.PackageRootResolver;
 import com.google.devtools.build.lib.actions.RemoteArtifactChecker;
 import com.google.devtools.build.lib.actions.ScanningActionEvent;
+import com.google.devtools.build.lib.actions.SpawnActionExecutionException;
 import com.google.devtools.build.lib.actions.SpawnResult;
 import com.google.devtools.build.lib.actions.SpawnResult.MetadataLog;
 import com.google.devtools.build.lib.actions.StoppedScanningActionEvent;
@@ -119,9 +121,9 @@
 import com.google.devtools.common.options.OptionsProvider;
 import java.io.FileNotFoundException;
 import java.io.IOException;
+import java.time.Instant;
 import java.util.List;
 import java.util.Map;
-import java.util.Objects;
 import java.util.Set;
 import java.util.SortedMap;
 import java.util.concurrent.ConcurrentMap;
@@ -1801,20 +1803,31 @@ private static void reportActionExecution(
       ErrorTiming errorTiming) {
     Path stdout = null;
     Path stderr = null;
-    ImmutableList<MetadataLog> logs = ImmutableList.of();
 
     if (outErr.hasRecordedStdout()) {
       stdout = outErr.getOutputPath();
     }
     if (outErr.hasRecordedStderr()) {
       stderr = outErr.getErrorPath();
     }
-    if (actionResult != null) {
-      logs =
-          actionResult.spawnResults().stream()
-              .map(SpawnResult::getActionMetadataLog)
-              .filter(Objects::nonNull)
-              .collect(toImmutableList());
+    // Collect MetadataLogs and spawn start times/end times from the Action's SpawnResults.
+    ImmutableList<SpawnResult> spawnResults =
+        findSpawnResultsInActionResultAndException(actionResult, exception);
+    ImmutableList.Builder<MetadataLog> logs = ImmutableList.builder();
+    Instant firstStartTime = Instant.MAX;
+    Instant lastEndTime = Instant.MIN;
+    for (SpawnResult spawnResult : spawnResults) {
+      MetadataLog log = spawnResult.getActionMetadataLog();
+      if (log != null) {
+        logs.add(log);
+      }
+      // Not all SpawnResults have a start time, and some use Instant.MIN/MAX instead of null.
+      @Nullable Instant startTime = spawnResult.getStartTime();
+      if (startTime != null && !startTime.equals(Instant.MIN) && !startTime.equals(Instant.MAX)) {
+        Instant endTime = startTime.plusMillis(spawnResult.getWallTimeInMs());
+        firstStartTime = min(firstStartTime, startTime);
+        lastEndTime = max(lastEndTime, endTime);
+      }
     }
     eventHandler.post(
         new ActionExecutedEvent(
@@ -1826,8 +1839,27 @@ private static void reportActionExecution(
             primaryOutputMetadata,
             stdout,
             stderr,
-            logs,
-            errorTiming));
+            logs.build(),
+            errorTiming,
+            firstStartTime.equals(Instant.MAX) ? null : firstStartTime,
+            lastEndTime.equals(Instant.MIN) ? null : firstStartTime));
+  }
+
+  /**
+   * Extracts the {@link SpawnResult SpawnResults} from either a completed {@link ActionResult} or a
+   * {@link SpawnActionExecutionException}.
+   *
+   * <p>Returns an empty list for any other kind of {@link ActionExecutionException}.
+   */
+  private static ImmutableList<SpawnResult> findSpawnResultsInActionResultAndException(
+      @Nullable ActionResult actionResult, @Nullable ActionExecutionException exception) {
+    if (actionResult != null) {
+      return actionResult.spawnResults();
+    }
+    if (exception instanceof SpawnActionExecutionException) {
+      return ImmutableList.of(((SpawnActionExecutionException) exception).getSpawnResult());
+    }
+    return ImmutableList.of();
   }
 
   /** An object supplying data for action execution progress reporting. */
@@ -1840,6 +1872,7 @@ public interface ProgressSupplier {
   public interface ActionCompletedReceiver {
     /** Receives a completed action. */
     void actionCompleted(ActionLookupData actionLookupData);
+
     /** Notes that an action has started, giving the key. */
     void noteActionEvaluationStarted(ActionLookupData actionLookupData, Action action);
   }

src/test/java/com/google/devtools/build/lib/runtime/BuildEventStreamerTest.java

@@ -142,14 +142,16 @@ public BuildEventProtocolOptions getOptions() {
       new ActionExecutedEvent(
           ActionsTestUtil.DUMMY_ARTIFACT.getExecPath(),
           new ActionsTestUtil.NullAction(),
-          /*exception=*/ null,
+          /* exception= */ null,
           ActionsTestUtil.DUMMY_ARTIFACT.getPath(),
           ActionsTestUtil.DUMMY_ARTIFACT,
           FileArtifactValue.OMITTED_FILE_MARKER,
-          /*stdout=*/ null,
-          /*stderr=*/ null,
-          /*actionMetadataLogs=*/ ImmutableList.of(),
-          ErrorTiming.NO_ERROR);
+          /* stdout= */ null,
+          /* stderr= */ null,
+          /* actionMetadataLogs= */ ImmutableList.of(),
+          ErrorTiming.NO_ERROR,
+          /* startTime= */ null,
+          /* endTime= */ null);
 
   private static final class RecordingBuildEventTransport implements BuildEventTransport {
     private final List<BuildEvent> events = new ArrayList<>();
@@ -1251,11 +1253,13 @@ public void testSuccessfulActionsAreNotPublishedByDefault() {
                         .build())),
             ActionsTestUtil.DUMMY_ARTIFACT.getPath(),
             ActionsTestUtil.DUMMY_ARTIFACT,
-            /*primaryOutputMetadata=*/ null,
-            /*stdout=*/ null,
-            /*stderr=*/ null,
-            /*actionMetadataLogs=*/ ImmutableList.of(),
-            ErrorTiming.BEFORE_EXECUTION);
+            /* primaryOutputMetadata= */ null,
+            /* stdout= */ null,
+            /* stderr= */ null,
+            /* actionMetadataLogs= */ ImmutableList.of(),
+            ErrorTiming.BEFORE_EXECUTION,
+            /* startTime= */ null,
+            /* endTime= */ null);
 
     streamer.buildEvent(SUCCESSFUL_ACTION_EXECUTED_EVENT);
     streamer.buildEvent(failedActionExecutedEvent);
@@ -1295,11 +1299,13 @@ public void testSuccessfulActionsCanBePublished() {
                         .build())),
             ActionsTestUtil.DUMMY_ARTIFACT.getPath(),
             ActionsTestUtil.DUMMY_ARTIFACT,
-            /*primaryOutputMetadata=*/ null,
-            /*stdout=*/ null,
-            /*stderr=*/ null,
-            /*actionMetadataLogs=*/ ImmutableList.of(),
-            ErrorTiming.BEFORE_EXECUTION);
+            /* primaryOutputMetadata= */ null,
+            /* stdout= */ null,
+            /* stderr= */ null,
+            /* actionMetadataLogs= */ ImmutableList.of(),
+            ErrorTiming.BEFORE_EXECUTION,
+            /* startTime= */ null,
+            /* endTime= */ null);
 
     streamer.buildEvent(SUCCESSFUL_ACTION_EXECUTED_EVENT);
     streamer.buildEvent(failedActionExecutedEvent);
@@ -1509,10 +1515,12 @@ private static ActionExecutedEvent createActionExecutedEventWithLogs(
         ActionsTestUtil.DUMMY_ARTIFACT.getPath(),
         ActionsTestUtil.DUMMY_ARTIFACT,
         FileArtifactValue.OMITTED_FILE_MARKER,
-        /*stdout=*/ null,
-        /*stderr=*/ null,
+        /* stdout= */ null,
+        /* stderr= */ null,
         metadataLogs,
-        ErrorTiming.NO_ERROR);
+        ErrorTiming.NO_ERROR,
+        /* startTime= */ null,
+        /* endTime= */ null);
   }
 
   @Test