[tools] Remove TestFailedError and generate Output object for all cases

This is part of the refactoring to allow exporting more information about test
execution to the recipes and upload this information to ChromePerf.

This fixes running secondary even after primary run fails, which will allow us
to differentiate between test and infra failures as latter ones will also affect
refbuilds and re-runs without patch.

R=machenbach@chromium.org, tmrts@chromium.org

Bug: chromium:841700
Change-Id: I29ce49d2f8c5e73158f1d41a73c51f2b35929f36
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/1570006
Commit-Queue: Sergiy Belozorov <sergiyb@chromium.org>
Reviewed-by: Michael Achenbach <machenbach@chromium.org>
Cr-Commit-Position: refs/heads/master@{#60946}

tools/run_perf.py

@@ -109,7 +109,6 @@ from functools import reduce
 
 from collections import OrderedDict
 import copy
-import datetime
 import json
 import logging
 import math
@@ -118,12 +117,13 @@ import os
 import re
 import subprocess
 import sys
+import time
 import traceback
 
 from testrunner.local import android
 from testrunner.local import command
 from testrunner.local import utils
-from testrunner.objects.output import Output
+from testrunner.objects.output import Output, NULL_OUTPUT
 
 try:
   basestring       # Python 2
@@ -154,11 +154,6 @@ def GeometricMean(values):
   return str(math.exp(sum(map(math.log, values)) / len(values)))
 
 
-class TestFailedError(Exception):
-  """Error raised when a test has failed due to a non-infra issue."""
-  pass
-
-
 class Results(object):
   """Place holder for result traces."""
   def __init__(self, traces=None, errors=None):
@@ -205,7 +200,6 @@ class Measurement(object):
     self.results = []
     self.errors = []
     self.stddev = ''
-    self.process_size = False
 
   def ConsumeOutput(self, output):
     try:
@@ -260,7 +254,7 @@ def Unzip(iterable):
 
 def RunResultsProcessor(results_processor, output, count):
   # Dummy pass through for null-runs.
-  if output is None or output.stdout is None:
+  if output.stdout is None:
     return output
 
   # We assume the results processor is relative to the suite.
@@ -292,7 +286,7 @@ def AccumulateResults(
                          This is needed so that we reuse this script for both CI
                          and trybot, but want to ignore second run on CI without
                          having to spread this logic throughout the script.
-    calc_total: Boolean flag to speficy the calculation of a summary trace.
+    calc_total: Boolean flag to specify the calculation of a summary trace.
   Returns: A 'Results' object.
   """
   measurements = [
@@ -339,8 +333,7 @@ def AccumulateGenericResults(graph_names, suite_units, output_iter):
   """
   traces = OrderedDict()
   for output in output_iter():
-    if output is None:
-      # The None value is used as a null object to simplify logic.
+    if output.stdout is None:
       continue
     for line in output.stdout.strip().splitlines():
       match = GENERIC_RESULTS_RE.match(line)
@@ -580,6 +573,7 @@ class RunnableTraceConfig(TraceConfig, RunnableConfig):
     )
 
 
+# TODO(sergiyb): Deprecate and remove. No benchmarks are using this code.
 class RunnableGenericConfig(RunnableConfig):
   """Represents a runnable suite definition with generic traces."""
   def __init__(self, suite, parent, arch):
@@ -674,16 +668,26 @@ class Platform(object):
     raise NotImplementedError()  # pragma: no cover
 
   def _TimedRun(self, runnable, count, secondary=False):
-    runnable_start_time = datetime.datetime.utcnow()
-    stdout = self._Run(runnable, count, secondary)
-    runnable_duration = datetime.datetime.utcnow() - runnable_start_time
-    if runnable_duration.total_seconds() > 0.9 * runnable.timeout:
+    suffix = ' - secondary' if secondary else ''
+    title = '>>> %%s (#%d)%s:' % ((count + 1), suffix)
+    try:
+      output = self._Run(runnable, count, secondary)
+    except OSError:
+      logging.exception(title % 'OSError')
+      raise
+    if output.duration > 0.9 * runnable.timeout:
       runnable.has_near_timeouts = True
-    # TODO(sergiyb): Move creating this object closer to the actual command
-    # execution and popupate more fields with actual data.
-    return Output(
-        exit_code=0, timed_out=False, stdout=stdout, stderr=None, pid=None,
-        duration=runnable_duration)
+    if output.stdout:
+      logging.info(title % 'Stdout' + '\n%s', output.stdout)
+    if output.stderr:  # pragma: no cover
+      # Print stderr for debugging.
+      logging.info(title % 'Stderr' + '\n%s', output.stderr)
+    if output.timed_out:
+      runnable.has_timeouts = True
+      logging.warning('>>> Test timed out after %ss.', runnable.timeout)
+    if output.exit_code != 0:
+      logging.warning('>>> Test crashed with exit code %d.', output.exit_code)
+    return output
 
   def Run(self, runnable, count):
     """Execute the benchmark's main file.
@@ -700,7 +704,7 @@ class Platform(object):
     if self.shell_dir_secondary:
       return output, self._TimedRun(runnable, count, secondary=True)
     else:
-      return output, None
+      return output, NULL_OUTPUT
 
 
 class DesktopPlatform(Platform):
@@ -740,24 +744,9 @@ class DesktopPlatform(Platform):
     shell_dir = self.shell_dir_secondary if secondary else self.shell_dir
     title = '>>> %%s (#%d)%s:' % ((count + 1), suffix)
     cmd = runnable.GetCommand(self.command_prefix, shell_dir, self.extra_flags)
-    try:
-      output = cmd.execute()
-    except OSError:  # pragma: no cover
-      logging.exception(title % 'OSError')
-      raise
+    output = cmd.execute()
 
-    logging.info(title % 'Stdout' + '\n%s', output.stdout)
-    if output.stderr:  # pragma: no cover
-      # Print stderr for debugging.
-      logging.info(title % 'Stderr' + '\n%s', output.stderr)
-    if output.timed_out:
-      logging.warning('>>> Test timed out after %ss.', runnable.timeout)
-      runnable.has_timeouts = True
-      raise TestFailedError()
-    if output.exit_code != 0:
-      logging.warning('>>> Test crashed.')
-      raise TestFailedError()
-    if '--prof' in self.extra_flags:
+    if output.IsSuccess() and '--prof' in self.extra_flags:
       os_prefix = {'linux': 'linux', 'macos': 'mac'}.get(utils.GuessOS())
       if os_prefix:
         tick_tools = os.path.join(TOOLS_BASE, '%s-tick-processor' % os_prefix)
@@ -766,10 +755,10 @@ class DesktopPlatform(Platform):
         logging.warning(
             'Profiler option currently supported on Linux and Mac OS.')
 
-    # time outputs to stderr
+    # /usr/bin/time outputs to stderr
     if runnable.process_size:
-      return output.stdout + output.stderr
-    return output.stdout
+      output.stdout += output.stderr
+    return output
 
 
 class AndroidPlatform(Platform):  # pragma: no cover
@@ -807,9 +796,7 @@ class AndroidPlatform(Platform):  # pragma: no cover
       self.driver.push_file(bench_abs, resource, bench_rel)
 
   def _Run(self, runnable, count, secondary=False):
-    suffix = ' - secondary' if secondary else ''
     target_dir = 'bin_secondary' if secondary else 'bin'
-    title = '>>> %%s (#%d)%s:' % ((count + 1), suffix)
     self.driver.drop_ram_caches()
 
     # Relative path to benchmark directory.
@@ -826,8 +813,10 @@ class AndroidPlatform(Platform):  # pragma: no cover
             runnable_name, count + 1, '-secondary' if secondary else ''))
       logging.debug('Dumping logcat into %s', logcat_file)
 
+    output = Output()
+    start = time.time()
     try:
-      stdout = self.driver.run(
+      output.stdout = self.driver.run(
           target_dir=target_dir,
           binary=runnable.binary,
           args=runnable.GetCommandFlags(self.extra_flags),
@@ -835,20 +824,16 @@ class AndroidPlatform(Platform):  # pragma: no cover
           timeout=runnable.timeout,
           logcat_file=logcat_file,
       )
-      logging.info(title % 'Stdout' + '\n%s', stdout)
     except android.CommandFailedException as e:
-      logging.info(title % 'Stdout' + '\n%s', e.output)
-      logging.warning('>>> Test crashed.')
-      raise TestFailedError()
+      output.stdout = e.output
+      output.exit_code = e.status
     except android.TimeoutException as e:
-      if e.output is not None:
-        logging.info(title % 'Stdout' + '\n%s', e.output)
-      logging.warning('>>> Test timed out after %ss.', runnable.timeout)
-      runnable.has_timeouts = True
-      raise TestFailedError()
+      output.stdout = e.output
+      output.timed_out = True
     if runnable.process_size:
-      return stdout + 'MaxMemory: Unsupported'
-    return stdout
+      output.stdout += 'MaxMemory: Unsupported'
+    output.duration = time.time() - start
+    return output
 
 class CustomMachineConfiguration:
   def __init__(self, disable_aslr = False, governor = None):
@@ -1127,16 +1112,15 @@ def Main(args):
           for i in range(0, max(1, total_runs)):
             attempts_left = runnable.retry_count + 1
             while attempts_left:
-              try:
-                yield platform.Run(runnable, i)
-              except TestFailedError:
-                attempts_left -= 1
-                if not attempts_left:  # ignore failures until last attempt
-                  have_failed_tests[0] = True
-                else:
-                  logging.info('>>> Retrying suite: %s', runnable_name)
-              else:
+              output, output_secondary = platform.Run(runnable, i)
+              if output.IsSuccess() and output_secondary.IsSuccess():
+                yield output, output_secondary
                 break
+              attempts_left -= 1
+              if not attempts_left:  # ignore failures until last attempt
+                have_failed_tests[0] = True
+              else:
+                logging.info('>>> Retrying suite: %s', runnable_name)
 
         # Let runnable iterate over all runs and handle output.
         result, result_secondary = runnable.Run(

tools/testrunner/objects/output.py

@@ -34,7 +34,8 @@ from ..local import utils
 
 class Output(object):
 
-  def __init__(self, exit_code, timed_out, stdout, stderr, pid, duration):
+  def __init__(self, exit_code=0, timed_out=False, stdout=None, stderr=None,
+               pid=None, duration=None):
     self.exit_code = exit_code
     self.timed_out = timed_out
     self.stdout = stdout
@@ -61,3 +62,16 @@ class Output(object):
 
   def HasTimedOut(self):
     return self.timed_out
+
+  def IsSuccess(self):
+    return not self.HasCrashed() and not self.HasTimedOut()
+
+
+class _NullOutput(Output):
+  """Useful to signal that the binary has not been run."""
+  def __init__(self):
+    super(_NullOutput, self).__init__()
+
+
+# Default instance of the _NullOutput class above.
+NULL_OUTPUT = _NullOutput()

tools/unittests/run_perf_test.py

@@ -88,8 +88,6 @@ V8_GENERIC_JSON = {
   'units': 'ms',
 }
 
-Output = namedtuple('Output', 'stdout, stderr, timed_out, exit_code')
-
 class PerfTest(unittest.TestCase):
   @classmethod
   def setUpClass(cls):
@@ -99,8 +97,8 @@ class PerfTest(unittest.TestCase):
     cls._cov.start()
     import run_perf
     from testrunner.local import command
-    global command
-    global run_perf
+    from testrunner.objects.output import Output, NULL_OUTPUT
+    global command, run_perf, Output, NULL_OUTPUT
 
   @classmethod
   def tearDownClass(cls):
@@ -127,7 +125,6 @@ class PerfTest(unittest.TestCase):
   def _MockCommand(self, *args, **kwargs):
     # Fake output for each test run.
     test_outputs = [Output(stdout=arg,
-                           stderr=None,
                            timed_out=kwargs.get('timed_out', False),
                            exit_code=kwargs.get('exit_code', 0))
                     for arg in args[1]]
@@ -427,7 +424,7 @@ class PerfTest(unittest.TestCase):
   def testOneRunCrashed(self):
     self._WriteTestInput(V8_JSON)
     self._MockCommand(
-        ['.'], ['x\nRichards: 1.234\nDeltaBlue: 10657567\ny\n'], exit_code=1)
+        ['.'], ['x\nRichards: 1.234\nDeltaBlue: 10657567\ny\n'], exit_code=-1)
     self.assertEquals(1, self._CallMain())
     self._VerifyResults('test', 'score', [
       {'name': 'Richards', 'results': [], 'stddev': ''},
@@ -456,12 +453,10 @@ class PerfTest(unittest.TestCase):
     mock.patch('run_perf.AndroidPlatform.PreExecution').start()
     mock.patch('run_perf.AndroidPlatform.PostExecution').start()
     mock.patch('run_perf.AndroidPlatform.PreTests').start()
-    mock_output = Output(
-        stdout='Richards: 1.234\nDeltaBlue: 10657567\n', stderr=None,
-        timed_out=False, exit_code=0)
     mock.patch(
         'run_perf.AndroidPlatform.Run',
-        return_value=(mock_output, None)).start()
+        return_value=(Output(stdout='Richards: 1.234\nDeltaBlue: 10657567\n'),
+                      NULL_OUTPUT)).start()
     mock.patch('testrunner.local.android._Driver', autospec=True).start()
     mock.patch(
         'run_perf.Platform.ReadBuildConfig',