Fix reported times for batched skipped tests

The ordering of events is different for skipped tests and completed
tests, so in order to support both skipped and completed tests
reporting duration I had to modify the python result generation code.

Now all tests report duration as a separate status after completion.

Bug: 989569
Change-Id: I1a837bc2707a1517db6fdea91220aace7e1745d8
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2218559Reviewed-by: Andrew Grieve <agrieve@chromium.org>
Commit-Queue: Michael Thiessen <mthiesse@chromium.org>
Cr-Commit-Position: refs/heads/master@{#772673}

base/test/android/javatests/src/org/chromium/base/test/BaseJUnit4ClassRunner.java

@@ -18,7 +18,6 @@ import org.junit.rules.MethodRule;
 import org.junit.rules.RuleChain;
 import org.junit.rules.TestRule;
 import org.junit.runner.Description;
-import org.junit.runner.notification.RunListener;
 import org.junit.runner.notification.RunNotifier;
 import org.junit.runners.model.FrameworkMethod;
 import org.junit.runners.model.InitializationError;
@@ -258,25 +257,13 @@ public class BaseJUnit4ClassRunner extends AndroidJUnit4ClassRunner {
 
         runPreTestHooks(method);
 
-        final long start = SystemClock.uptimeMillis();
-        RunListener listener = new RunListener() {
-            @Override
-            public void testFinished(Description description) {
-                long end = SystemClock.uptimeMillis();
-                Bundle b = new Bundle();
-                b.putLong(DURATION_BUNDLE_ID, end - start);
-                InstrumentationRegistry.getInstrumentation().sendStatus(
-                        STATUS_CODE_TEST_DURATION, b);
-            }
-        };
-        // Add listener ahead of other listeners to make parsing easier -
-        // Instrumentation prints the status code after the values corresponding
-        // to that status code, so if we output this status first, we can just
-        // ignore the status code line and have the parser include the values
-        // with the test compete bundle.
-        notifier.addFirstListener(listener);
+        long start = SystemClock.uptimeMillis();
+
         super.runChild(method, notifier);
-        notifier.removeListener(listener);
+
+        Bundle b = new Bundle();
+        b.putLong(DURATION_BUNDLE_ID, SystemClock.uptimeMillis() - start);
+        InstrumentationRegistry.getInstrumentation().sendStatus(STATUS_CODE_TEST_DURATION, b);
 
         TestTraceEvent.end(testName);
 

build/android/pylib/instrumentation/instrumentation_parser.py

@@ -79,10 +79,6 @@ class InstrumentationParser(object):
           key, value = value.split('=', 1)
           bundle[header][key] = [value]
         elif header == 'STATUS_CODE':
-          # To make parsing easier treat this as part of the next status by
-          # skipping it.
-          if int(value) == STATUS_CODE_TEST_DURATION:
-            continue
           yield int(value), join_bundle_values(bundle['STATUS'])
           bundle['STATUS'] = {}
         elif header == 'CODE':

build/android/pylib/instrumentation/instrumentation_test_instance.py

@@ -147,6 +147,16 @@ def GenerateTestResults(result_code, result_bundle, statuses, duration_ms,
   cumulative_duration = 0
 
   for status_code, bundle in statuses:
+    if status_code == instrumentation_parser.STATUS_CODE_TEST_DURATION:
+      # For the first result, duration will be set below to the difference
+      # between the reported and actual durations to account for overhead like
+      # starting instrumentation.
+      if len(results) > 1:
+        current_duration = int(bundle.get(_BUNDLE_DURATION_ID, duration_ms))
+        current_result.SetDuration(current_duration)
+        cumulative_duration += current_duration
+      continue
+
     test_class = bundle.get(_BUNDLE_CLASS_ID, '')
     test_method = bundle.get(_BUNDLE_TEST_ID, '')
     if test_class and test_method:
@@ -160,14 +170,6 @@ def GenerateTestResults(result_code, result_bundle, statuses, duration_ms,
       current_result = test_result.InstrumentationTestResult(
           test_name, base_test_result.ResultType.UNKNOWN, duration_ms)
     else:
-      # For the first result, duration will be set below to the difference
-      # between the reported and actual durations to account for overhead like
-      # starting instrumentation.
-      if bundle.get(_BUNDLE_CURRENT_ID, 1) != 1:
-        current_duration = int(bundle.get(_BUNDLE_DURATION_ID, duration_ms))
-        current_result.SetDuration(current_duration)
-        cumulative_duration += current_duration
-
       if status_code == instrumentation_parser.STATUS_CODE_OK:
         if bundle.get(_BUNDLE_SKIPPED_ID, '').lower() in ('true', '1', 'yes'):
           current_result.SetType(base_test_result.ResultType.SKIP)