BEP: provide timing information for tests

For tests, also provide information on the time the test took.

--
Change-Id: I8e71391e4dd97627d6293159a0cbb0d922683af7
Reviewed-on: https://cr.bazel.build/9214
PiperOrigin-RevId: 149547633
MOS_MIGRATED_REVID=149547633

5 files changed, 49 insertions, 3 deletions

diff --git a/src/main/java/com/google/devtools/build/lib/buildeventstream/proto/build_event_stream.proto b/src/main/java/com/google/devtools/build/lib/buildeventstream/proto/build_event_stream.proto
index c07430f9ce..072a7ef9ca 100644
--- a/src/main/java/com/google/devtools/build/lib/buildeventstream/proto/build_event_stream.proto
+++ b/src/main/java/com/google/devtools/build/lib/buildeventstream/proto/build_event_stream.proto
@@ -244,6 +244,9 @@ message TargetComplete {
 message TestResult {
   bool success = 1;
 
+  // Time the test took to run; unset if the test result was cached.
+  int64 test_attempt_duration_millis = 3;
+
   // Files (logs, test.xml, undeclared outputs, etc) generated by that test
   // action.
   repeated File test_action_output = 2;
diff --git a/src/main/java/com/google/devtools/build/lib/exec/StandaloneTestStrategy.java b/src/main/java/com/google/devtools/build/lib/exec/StandaloneTestStrategy.java
index 831183a059..ac42e147aa 100644
--- a/src/main/java/com/google/devtools/build/lib/exec/StandaloneTestStrategy.java
+++ b/src/main/java/com/google/devtools/build/lib/exec/StandaloneTestStrategy.java
@@ -170,7 +170,8 @@ public class StandaloneTestStrategy extends TestStrategy {
           .getEventBus()
           .post(
               new TestAttempt(
-                  action, attempt, data.getTestPassed(), testOutputsBuilder.build(), true));
+                  action, attempt, data.getTestPassed(), data.getRunDurationMillis(),
+                  testOutputsBuilder.build(), true));
       finalizeTest(actionExecutionContext, action, dataBuilder.build());
     } catch (IOException e) {
       executor.getEventHandler().handle(Event.error("Caught I/O exception: " + e));
@@ -211,7 +212,10 @@ public class StandaloneTestStrategy extends TestStrategy {
     dataBuilder.addAllTestProcessTimes(data.getTestProcessTimesList());
     executor
         .getEventBus()
-        .post(new TestAttempt(action, attempt, data.getTestPassed(), testOutputsBuilder.build()));
+        .post(
+            new TestAttempt(
+                action, attempt, data.getTestPassed(), data.getRunDurationMillis(),
+                testOutputsBuilder.build(), false));
     processTestOutput(executor, outErr, new TestResult(action, data, false), testLog);
   }
 
diff --git a/src/main/java/com/google/devtools/build/lib/rules/test/TestAttempt.java b/src/main/java/com/google/devtools/build/lib/rules/test/TestAttempt.java
index 6865e44e12..47f4f87b14 100644
--- a/src/main/java/com/google/devtools/build/lib/rules/test/TestAttempt.java
+++ b/src/main/java/com/google/devtools/build/lib/rules/test/TestAttempt.java
@@ -22,6 +22,7 @@ import com.google.devtools.build.lib.buildeventstream.GenericBuildEvent;
 import com.google.devtools.build.lib.buildeventstream.PathConverter;
 import com.google.devtools.build.lib.util.Pair;
 import com.google.devtools.build.lib.vfs.Path;
+import com.google.devtools.build.lib.view.test.TestStatus.TestResultData;
 import java.util.Collection;
 
 /** This event is raised whenever a an individual test attempt is completed. */
@@ -32,6 +33,7 @@ public class TestAttempt implements BuildEvent {
   private final int attempt;
   private final boolean lastAttempt;
   private final Collection<Pair<String, Path>> files;
+  private final long durationMillis;
 
   /**
    * Construct the event given the test action and attempt number.
@@ -43,11 +45,13 @@ public class TestAttempt implements BuildEvent {
       TestRunnerAction testAction,
       Integer attempt,
       boolean success,
+      long durationMillis,
       Collection<Pair<String, Path>> files,
       boolean lastAttempt) {
     this.testAction = testAction;
     this.attempt = attempt;
     this.success = success;
+    this.durationMillis = durationMillis;
     this.files = files;
     this.lastAttempt = lastAttempt;
   }
@@ -56,13 +60,24 @@ public class TestAttempt implements BuildEvent {
       TestRunnerAction testAction,
       Integer attempt,
       boolean success,
+      Collection<Pair<String, Path>> files,
+      boolean lastAttempt) {
+    this(testAction, attempt, success, 0, files, lastAttempt);
+  }
+
+  public TestAttempt(
+      TestRunnerAction testAction,
+      Integer attempt,
+      boolean success,
       Collection<Pair<String, Path>> files) {
     this(testAction, attempt, success, files, false);
   }
 
   public static TestAttempt fromCachedTestResult(TestResult result) {
+    TestResultData data = result.getData();
     return new TestAttempt(
-        result.getTestAction(), 1, result.getData().getTestPassed(), result.getFiles(), true);
+        result.getTestAction(), 1, data.getTestPassed(), data.getRunDurationMillis(),
+        result.getFiles(), true);
   }
 
   @Override
@@ -93,6 +108,7 @@ public class TestAttempt implements BuildEvent {
     BuildEventStreamProtos.TestResult.Builder builder =
         BuildEventStreamProtos.TestResult.newBuilder();
     builder.setSuccess(success);
+    builder.setTestAttemptDurationMillis(durationMillis);
     for (Pair<String, Path> file : files) {
       builder.addTestActionOutput(
           BuildEventStreamProtos.File.newBuilder()
diff --git a/src/test/shell/integration/BUILD b/src/test/shell/integration/BUILD
index d5528d7fdf..729af75b84 100644
--- a/src/test/shell/integration/BUILD
+++ b/src/test/shell/integration/BUILD
@@ -225,6 +225,7 @@ sh_test(
     size = "medium",
     srcs = ["build_event_stream_test.sh"],
     data = [":test-deps"],
+    shard_count = 2,
 )
 
 sh_test(
diff --git a/src/test/shell/integration/build_event_stream_test.sh b/src/test/shell/integration/build_event_stream_test.sh
index f875389e16..e9700acad8 100755
--- a/src/test/shell/integration/build_event_stream_test.sh
+++ b/src/test/shell/integration/build_event_stream_test.sh
@@ -37,11 +37,21 @@ EOF
 exit 1
 EOF
   chmod 755 pkg/false.sh
+  cat > pkg/slowtest.sh <<EOF
+#!/bin/sh
+sleep 1
+exit 0
+EOF
+  chmod 755 pkg/slowtest.sh
   cat > pkg/BUILD <<EOF
 sh_test(
   name = "true",
   srcs = ["true.sh"],
 )
+sh_test(
+  name = "slow",
+  srcs = ["slowtest.sh"],
+)
 test_suite(
   name = "suite",
   tests = ["true"],
@@ -146,6 +156,18 @@ function test_test_attempts() {
   expect_log 'name:.*test.xml'
 }
 
+function test_test_runtime() {
+  bazel test --experimental_build_event_text_file=$TEST_log pkg:slow \
+    || fail "bazel test failed"
+  expect_log 'pkg:slow'
+  expect_log '^test_result'
+  expect_log 'test_attempt_duration_millis.*[1-9]'
+  expect_log 'build_finished'
+  expect_log 'overall_success: true'
+  expect_log 'finish_time'
+  expect_not_log 'aborted'
+}
+
 function test_test_attempts_multi_runs() {
   # Sanity check on individual test attempts. Even in more complicated
   # situations, with some test rerun and some not, all events are properly