Add concept of slow tests.

webkit/tools/layout_tests/run_webkit_tests.py

 #!/bin/env python
 # Copyright (c) 2006-2008 The Chromium Authors. All rights reserved.
 # Use of this source code is governed by a BSD-style license that can be
 # found in the LICENSE file.
 
 """Run layout tests using the test_shell.
 
 This is a port of the existing webkit test script run-webkit-tests.
 
 The TestRunner class runs a series of tests (TestType interface) against a set
@@ skipping 30 matching lines @@
 from layout_package import path_utils
 from layout_package import platform_utils
 from layout_package import test_failures
 from layout_package import test_shell_thread
 from test_types import fuzzy_image_diff
 from test_types import image_diff
 from test_types import test_type_base
 from test_types import text_diff
 from test_types import simplified_text_diff
 
+class TestInfo:
+  """Groups information about a test for easy passing of data."""
+  def __init__(self, filename, timeout):
+    """Generates the URI and stores the filename and timeout for this test.
+    Args:
+      filename: Full path to the test.
+      timeout: Timeout for running the test in TestShell.
+      """
+    self.filename = filename
+    self.uri = path_utils.FilenameToUri(filename)
+    self.timeout = timeout
+
 
 class TestRunner:
   """A class for managing running a series of tests on a series of test
   files."""
 
   # When collecting test cases, we include any file with these extensions.
   _supported_file_extensions = set(['.html', '.shtml', '.xml', '.xhtml', '.pl',
                                     '.php', '.svg'])
   # When collecting test cases, skip these directories
   _skipped_directories = set(['.svn', '_svn', 'resources'])
@@ skipping 271 matching lines @@
   def _GetTestFileQueue(self, test_files):
     """Create the thread safe queue of lists of (test filenames, test URIs)
     tuples. Each TestShellThread pulls a list from this queue and runs those
     tests in order before grabbing the next available list.
 
     Shard the lists by directory. This helps ensure that tests that depend
     on each other (aka bad tests!) continue to run together as most
     cross-tests dependencies tend to occur within the same directory.
 
     Return:
-      The Queue of lists of (test file, test uri) tuples.
+      The Queue of lists of TestInfo objects.
     """
     tests_by_dir = {}
     for test_file in test_files:
       directory = self._GetDirForTestFile(test_file)
       if directory not in tests_by_dir:
         tests_by_dir[directory] = []
-      tests_by_dir[directory].append((test_file,
-          path_utils.FilenameToUri(test_file)))
+
+      if self._expectations.HasModifier(test_file, test_expectations.SLOW):
+        timeout = 10 * int(options.time_out_ms)
+      else:
+        timeout = self._options.time_out_ms
+
+      tests_by_dir[directory].append(TestInfo(test_file, timeout))
 
     # Sort by the number of tests in the dir so that the ones with the most
     # tests get run first in order to maximize parallelization. Number of tests
     # is a good enough, but not perfect, approximation of how long that set of
     # tests will take to run. We can't just use a PriorityQueue until we move
     # to Python 2.6.
     test_lists = []
     http_tests = None
     for directory in tests_by_dir:
       test_list = tests_by_dir[directory]
@@ skipping 30 matching lines @@
 
     test_args.new_baseline = self._options.new_baseline
     test_args.show_sources = self._options.sources
 
     if self._options.startup_dialog:
       shell_args.append('--testshell-startup-dialog')
 
     if self._options.gp_fault_error_box:
       shell_args.append('--gp-fault-error-box')
 
-    # larger timeout if page heap is enabled.
-    if self._options.time_out_ms:
-      shell_args.append('--time-out-ms=' + self._options.time_out_ms)
-
     return (test_args, shell_args)
 
   def _InstantiateTestShellThreads(self, test_shell_binary):
     """Instantitates and starts the TestShellThread(s).
 
     Return:
       The list of threads.
     """
     test_shell_command = [test_shell_binary]
 
@@ skipping 57 matching lines @@
         sys.exit(1)
 
     logging.info("Starting tests")
 
     # Create the output directory if it doesn't already exist.
     google.path_utils.MaybeMakeDirectory(self._options.results_directory)
 
     threads = self._InstantiateTestShellThreads(test_shell_binary)
 
     # Wait for the threads to finish and collect test failures.
-    test_failures = {}
+    failures = {}
     test_timings = {}
     individual_test_timings = []
     try:
       for thread in threads:
         while thread.isAlive():
           # Let it timeout occasionally so it can notice a KeyboardInterrupt
           # Actually, the timeout doesn't really matter: apparently it
           # suffices to not use an indefinite blocking join for it to
           # be interruptible by KeyboardInterrupt.
           thread.join(1.0)
-        test_failures.update(thread.GetFailures())
+        failures.update(thread.GetFailures())
         test_timings.update(thread.GetDirectoryTimingStats())
         individual_test_timings.extend(thread.GetIndividualTestStats())
     except KeyboardInterrupt:
       for thread in threads:
         thread.Cancel()
       raise
     for thread in threads:
       # Check whether a TestShellThread died before normal completion.
       exception_info = thread.GetExceptionInfo()
       if exception_info is not None:
         # Re-raise the thread's exception here to make it clear that
         # testing was aborted. Otherwise, the tests that did not run
         # would be assumed to have passed.
         raise exception_info[0], exception_info[1], exception_info[2]
 
     print
     end_time = time.time()
     logging.info("%f total testing time" % (end_time - start_time))
 
     print
-    self._PrintTimingStatistics(test_timings, individual_test_timings)
+    self._PrintTimingStatistics(test_timings, individual_test_timings, failures)
 
     print "-" * 78
 
     # Tests are done running. Compare failures with expected failures.
-    regressions = self._CompareFailures(test_failures)
+    regressions = self._CompareFailures(failures)
 
     print "-" * 78
 
     # Write summaries to stdout.
-    self._PrintResults(test_failures, sys.stdout)
+    self._PrintResults(failures, sys.stdout)
 
     # Write the same data to a log file.
     out_filename = os.path.join(self._options.results_directory, "score.txt")
     output_file = open(out_filename, "w")
-    self._PrintResults(test_failures, output_file)
+    self._PrintResults(failures, output_file)
     output_file.close()
 
     # Write the summary to disk (results.html) and maybe open the test_shell
     # to this file.
-    wrote_results = self._WriteResultsHtmlFile(test_failures, regressions)
+    wrote_results = self._WriteResultsHtmlFile(failures, regressions)
     if not self._options.noshow_results and wrote_results:
       self._ShowResultsHtmlFile()
 
     sys.stdout.flush()
     sys.stderr.flush()
     return len(regressions)
 
   def _PrintTimingStatistics(self, directory_test_timings,
-      individual_test_timings):
+      individual_test_timings, failures):
+    self._PrintAggregateTestStatistics(individual_test_timings)
+    self._PrintIndividualTestTimes(individual_test_timings, failures)
+    self._PrintDirectoryTimings(directory_test_timings)
+
+  def _PrintAggregateTestStatistics(self, individual_test_timings):
+    """Prints aggregate statistics (e.g. median, mean, etc.) for all tests.
+    Args:
+      individual_test_timings: List of test_shell_thread.TestStats for all
+          tests.
+    """
     test_types = individual_test_timings[0].time_for_diffs.keys()
     times_for_test_shell = []
     times_for_diff_processing = []
     times_per_test_type = {}
     for test_type in test_types:
       times_per_test_type[test_type] = []
 
     for test_stats in individual_test_timings:
       times_for_test_shell.append(test_stats.test_run_time)
       times_for_diff_processing.append(test_stats.total_time_for_all_diffs)
       time_for_diffs = test_stats.time_for_diffs
       for test_type in test_types:
         times_per_test_type[test_type].append(time_for_diffs[test_type])
 
-    logging.debug("PER TEST TIME IN TESTSHELL (seconds):")
-    self._PrintStatisticsForTestTimings(times_for_test_shell)
-    logging.debug("PER TEST DIFF PROCESSING TIMES (seconds):")
-    self._PrintStatisticsForTestTimings(times_for_diff_processing)
+    self._PrintStatisticsForTestTimings(
+        "PER TEST TIME IN TESTSHELL (seconds):",
+        times_for_test_shell)
+    self._PrintStatisticsForTestTimings(
+        "PER TEST DIFF PROCESSING TIMES (seconds):",
+        times_for_diff_processing)
     for test_type in test_types:
-      logging.debug("TEST TYPE: %s" % test_type)
-      self._PrintStatisticsForTestTimings(times_per_test_type[test_type])
+      self._PrintStatisticsForTestTimings(
+          "PER TEST TIMES BY TEST TYPE: %s" % test_type,
+          times_per_test_type[test_type])
 
+  def _PrintIndividualTestTimes(self, individual_test_timings, failures):
+    """Prints the run times for slow, timeout and crash tests.
+    Args:
+      individual_test_timings: List of test_shell_thread.TestStats for all
+          tests.
+      failures: Dictionary mapping test filenames to list of test_failures.
+    """
     # Reverse-sort by the time spent in test_shell.
     individual_test_timings.sort(lambda a, b:
         cmp(b.test_run_time, a.test_run_time))
-    slowests_tests = (
-        individual_test_timings[:self._options.num_slow_tests_to_log] )
 
-    logging.debug("%s slowest tests:" % self._options.num_slow_tests_to_log)
-    for test in slowests_tests:
-      logging.debug("%s took %s seconds" % (test.filename,
-          round(test.test_run_time, 1)))
+    num_printed = 0
+    slow_tests = []
+    timeout_or_crash_tests = []
+    unexpected_slow_tests = []
+    for test_tuple in individual_test_timings:
+      filename = test_tuple.filename
+      is_timeout_crash_or_slow = False
+      if self._expectations.HasModifier(filename, test_expectations.SLOW):
+        is_timeout_crash_or_slow = True
+        slow_tests.append(test_tuple)
+
+      if filename in failures:
+        for failure in failures[filename]:
+          if (failure.__class__ == test_failures.FailureTimeout or
+              failure.__class__ == test_failures.FailureCrash):
+            is_timeout_crash_or_slow = True
+            timeout_or_crash_tests.append(test_tuple)
+            break
+
+      if (not is_timeout_crash_or_slow and
+          num_printed < self._options.num_slow_tests_to_log):
+        num_printed = num_printed + 1
+        unexpected_slow_tests.append(test_tuple)
 
     print
+    self._PrintTestListTiming("%s slowest tests that are not marked as SLOW "
+        "and did not timeout/crash:" % self._options.num_slow_tests_to_log,
+        unexpected_slow_tests)
+    print
+    self._PrintTestListTiming("Tests marked as SLOW:", slow_tests)
+    print
+    self._PrintTestListTiming("Tests that timed out or crashed:",
+        timeout_or_crash_tests)
+    print
 
+  def _PrintTestListTiming(self, title, test_list):
+    logging.debug(title)
+    for test_tuple in test_list:
+      filename = test_tuple.filename[len(path_utils.LayoutDataDir()) + 1:]
+      filename = filename.replace('\\', '/')
+      test_run_time = round(test_tuple.test_run_time, 1)
+      logging.debug("%s took %s seconds" % (filename, test_run_time))
+
+  def _PrintDirectoryTimings(self, directory_test_timings):
     timings = []
     for directory in directory_test_timings:
       num_tests, time_for_directory = directory_test_timings[directory]
       timings.append((round(time_for_directory, 1), directory, num_tests))
     timings.sort()
 
     logging.debug("Time to process each subdirectory:")
     for timing in timings:
       logging.debug("%s took %s seconds to run %s tests." % \
                     (timing[1], timing[0], timing[2]))
 
-  def _PrintStatisticsForTestTimings(self, timings):
+  def _PrintStatisticsForTestTimings(self, title, timings):
     """Prints the median, mean and standard deviation of the values in timings.
     Args:
+      title: Title for these timings.
       timings: A list of floats representing times.
     """
+    logging.debug(title)
+    timings.sort()
+
     num_tests = len(timings)
+    percentile90 = timings[int(.9 * num_tests)]
+    percentile99 = timings[int(.99 * num_tests)]
+
     if num_tests % 2 == 1:
       median = timings[((num_tests - 1) / 2) - 1]
     else:
       lower = timings[num_tests / 2 - 1]
       upper = timings[num_tests / 2]
       median = (float(lower + upper)) / 2
 
     mean = sum(timings) / num_tests
 
     for time in timings:
       sum_of_deviations = math.pow(time - mean, 2)
 
     std_deviation = math.sqrt(sum_of_deviations / num_tests)
-    logging.debug(("Median: %s, Mean %s, Standard deviation: %s\n" %
-        (median, mean, std_deviation)))
+    logging.debug(("Median: %s, Mean: %s, 90th percentile: %s, "
+        "99th percentile: %s, Standard deviation: %s\n" % (
+        median, mean, percentile90, percentile99, std_deviation)))
 
-  def _PrintResults(self, test_failures, output):
+  def _PrintResults(self, failures, output):
     """Print a short summary to stdout about how many tests passed.
 
     Args:
-      test_failures is a dictionary mapping the test filename to a list of
+      failures is a dictionary mapping the test filename to a list of
       TestFailure objects if the test failed
 
       output is the file descriptor to write the results to. For example,
       sys.stdout.
     """
 
     failure_counts = {}
     deferred_counts = {}
     fixable_counts = {}
     non_ignored_counts = {}
     fixable_failures = set()
     deferred_failures = set()
     non_ignored_failures = set()
 
     # Aggregate failures in a dictionary (TestFailure -> frequency),
     # with known (fixable and ignored) failures separated out.
     def AddFailure(dictionary, key):
       if key in dictionary:
         dictionary[key] += 1
       else:
         dictionary[key] = 1
 
-    for test, failures in test_failures.iteritems():
+    for test, failures in failures.iteritems():
       for failure in failures:
         AddFailure(failure_counts, failure.__class__)
         if self._expectations.IsDeferred(test):
           AddFailure(deferred_counts, failure.__class__)
           deferred_failures.add(test)
         else:
           if self._expectations.IsFixable(test):
             AddFailure(fixable_counts, failure.__class__)
             fixable_failures.add(test)
           if not self._expectations.IsIgnored(test):
@@ skipping 25 matching lines @@
                              self._expectations.GetDeferred(),
                              deferred_failures,
                              deferred_counts,
                              self._expectations.GetDeferredSkipped(),
                              output)
 
     # Print breakdown of all tests including all skipped tests.
     skipped |= self._expectations.GetWontFixSkipped()
     self._PrintResultSummary("=> All tests",
                              self._test_files,
-                             test_failures,
+                             failures,
                              failure_counts,
                              skipped,
                              output)
     print
 
   def _PrintResultSummary(self, heading, all, failed, failure_counts, skipped,
                           output):
     """Print a summary block of results for a particular category of test.
 
     Args:
@@ skipping 18 matching lines @@
 
   def _PrintResultLine(self, count, total, message, output):
     if count == 0: return
     output.write(
         ("%(count)d test case%(plural)s (%(percent).1f%%) %(message)s\n" %
             { 'count'   : count,
               'plural'  : ('s', '')[count == 1],
               'percent' : float(count) * 100 / total,
               'message' : message }))
 
-  def _CompareFailures(self, test_failures):
+  def _CompareFailures(self, failures):
     """Determine how the test failures from this test run differ from the
     previous test run and print results to stdout and a file.
 
     Args:
-      test_failures is a dictionary mapping the test filename to a list of
+      failures is a dictionary mapping the test filename to a list of
       TestFailure objects if the test failed
 
     Return:
       A set of regressions (unexpected failures, hangs, or crashes)
     """
     cf = compare_failures.CompareFailures(self._test_files,
-                                          test_failures,
+                                          failures,
                                           self._expectations)
 
     if not self._options.nocompare_failures:
       cf.PrintRegressions(sys.stdout)
 
       out_filename = os.path.join(self._options.results_directory,
                                   "regressions.txt")
       output_file = open(out_filename, "w")
       cf.PrintRegressions(output_file)
       output_file.close()
 
     return cf.GetRegressions()
 
-  def _WriteResultsHtmlFile(self, test_failures, regressions):
+  def _WriteResultsHtmlFile(self, failures, regressions):
     """Write results.html which is a summary of tests that failed.
 
     Args:
-      test_failures: a dictionary mapping the test filename to a list of
+      failures: a dictionary mapping the test filename to a list of
           TestFailure objects if the test failed
       regressions: a set of test filenames that regressed
 
     Returns:
       True if any results were written (since expected failures may be omitted)
     """
     # test failures
     if self._options.full_results_html:
-      test_files = test_failures.keys()
+      test_files = failures.keys()
     else:
       test_files = list(regressions)
     if not len(test_files):
       return False
 
     out_filename = os.path.join(self._options.results_directory,
                                 "results.html")
     out_file = open(out_filename, 'w')
     # header
     if self._options.full_results_html:
       h2 = "Test Failures"
     else:
       h2 = "Unexpected Test Failures"
     out_file.write("<html><head><title>Layout Test Results (%(time)s)</title>"
                    "</head><body><h2>%(h2)s (%(time)s)</h2>\n"
                    % {'h2': h2, 'time': time.asctime()})
 
     test_files.sort()
     for test_file in test_files:
-      if test_file in test_failures: failures = test_failures[test_file]
+      if test_file in failures: failures = failures[test_file]
       else: failures = []  # unexpected passes
       out_file.write("<p><a href='%s'>%s</a><br />\n"
                      % (path_utils.FilenameToUri(test_file),
                         path_utils.RelativeTestFilename(test_file)))
       for failure in failures:
         out_file.write("&nbsp;&nbsp;%s<br/>"
                        % failure.ResultHtmlOutput(
                          path_utils.RelativeTestFilename(test_file)))
       out_file.write("</p>\n")
 
@@ skipping 180 matching lines @@
                            default=False,
                            help="Run all tests, even those marked SKIP in the "
                                 "test list")
   option_parser.add_option("", "--nocompare-failures", action="store_true",
                            default=False,
                            help="Disable comparison to the last test run. "
                                 "When enabled, show stats on how many tests "
                                 "newly pass or fail.")
   option_parser.add_option("", "--num-test-shells",
                            help="Number of testshells to run in parallel.")
-  option_parser.add_option("", "--time-out-ms",
-                           default=None,
+  option_parser.add_option("", "--time-out-ms", default=None,
                            help="Set the timeout for each test")
   option_parser.add_option("", "--run-singly", action="store_true",
                            default=False,
                            help="run a separate test_shell for each test")
   option_parser.add_option("", "--debug", action="store_true", default=False,
                            help="use the debug binary instead of the release "
                                 "binary")
   option_parser.add_option("", "--num-slow-tests-to-log", default=50,
                            help="Number of slow tests whose timings to print.")
   option_parser.add_option("", "--platform",
@@ skipping 35 matching lines @@
   option_parser.add_option("", "--run-part",
                            default=None,
                            help=("Run a specified part (n:m), the nth of m"
                                  " parts, of the layout tests"))
   option_parser.add_option("", "--batch-size",
                            default=None,
                            help=("Run a the tests in batches (n), after every "
                                  "n tests, the test shell is relaunched."))
   options, args = option_parser.parse_args()
   main(options, args)