2010-04-20 Dirk Pranke <dpranke@chromium.org>
authordpranke@chromium.org <dpranke@chromium.org@268f45cc-cd09-0410-ab3c-d52691b4dbfc>
Tue, 20 Apr 2010 22:43:51 +0000 (22:43 +0000)
committerdpranke@chromium.org <dpranke@chromium.org@268f45cc-cd09-0410-ab3c-d52691b4dbfc>
Tue, 20 Apr 2010 22:43:51 +0000 (22:43 +0000)
        This patch to new-run-webkit-tests adds a --log 'trace' option
        that prints out detailed info about a given test as it executes
        (where the baselines are, what the expectation is, what we got,
        how long it took).

        https://bugs.webkit.org/show_bug.cgi?id=37726

        * Scripts/webkitpy/layout_tests/run_webkit_tests.py:
          - use the newly exposed TestResult class and implement
            --log trace
        * Scripts/webkitpy/layout_tests/layout_package/dump_render_thread.py:
          - rename TestStats to TestResult and make it more public, resulting
            in cleaner code
        * Scripts/webkitpy/layout_tests/layout_package/test_expectations.py:
          - add expectation_to_string() as a separate callable function

git-svn-id: https://svn.webkit.org/repository/webkit/trunk@57934 268f45cc-cd09-0410-ab3c-d52691b4dbfc

WebKitTools/ChangeLog
WebKitTools/Scripts/webkitpy/layout_tests/layout_package/dump_render_tree_thread.py
WebKitTools/Scripts/webkitpy/layout_tests/layout_package/test_expectations.py
WebKitTools/Scripts/webkitpy/layout_tests/run_webkit_tests.py

index aa046fd..cdba446 100644 (file)
@@ -1,3 +1,21 @@
+2010-04-20  Dirk Pranke <dpranke@chromium.org>
+
+        This patch to new-run-webkit-tests adds a --log 'trace' option
+        that prints out detailed info about a given test as it executes
+        (where the baselines are, what the expectation is, what we got,
+        how long it took).
+
+        https://bugs.webkit.org/show_bug.cgi?id=37726
+
+        * Scripts/webkitpy/layout_tests/run_webkit_tests.py:
+          - use the newly exposed TestResult class and implement
+            --log trace
+        * Scripts/webkitpy/layout_tests/layout_package/dump_render_thread.py:
+          - rename TestStats to TestResult and make it more public, resulting
+            in cleaner code
+        * Scripts/webkitpy/layout_tests/layout_package/test_expectations.py:
+          - add expectation_to_string() as a separate callable function
+
 2010-04-20  Eric Seidel  <eric@webkit.org>
 
         Unreviewed, rolling out r57907.
index 93b4c79..9148f29 100644 (file)
@@ -54,8 +54,8 @@ _log = logging.getLogger("webkitpy.layout_tests.layout_package."
 def process_output(port, test_info, test_types, test_args, configuration,
                    output_dir, crash, timeout, test_run_time, actual_checksum,
                    output, error):
-    """Receives the output from a DumpRenderTree process, subjects it to a number
-    of tests, and returns a list of failure types the test produced.
+    """Receives the output from a DumpRenderTree process, subjects it to a
+    number of tests, and returns a list of failure types the test produced.
 
     Args:
       port: port-specific hooks
@@ -66,7 +66,7 @@ def process_output(port, test_info, test_types, test_args, configuration,
       configuration: Debug or Release
       output_dir: directory to put crash stack traces into
 
-    Returns: a list of failure objects and times for the test being processed
+    Returns: a TestResult object
     """
     failures = []
 
@@ -111,19 +111,20 @@ def process_output(port, test_info, test_types, test_args, configuration,
             time.time() - start_diff_time)
 
     total_time_for_all_diffs = time.time() - start_diff_time
-    return TestStats(test_info.filename, failures, test_run_time,
-        total_time_for_all_diffs, time_for_diffs)
+    return TestResult(test_info.filename, failures, test_run_time,
+                      total_time_for_all_diffs, time_for_diffs)
 
 
-class TestStats:
+class TestResult(object):
 
     def __init__(self, filename, failures, test_run_time,
                  total_time_for_all_diffs, time_for_diffs):
-        self.filename = filename
         self.failures = failures
+        self.filename = filename
         self.test_run_time = test_run_time
-        self.total_time_for_all_diffs = total_time_for_all_diffs
         self.time_for_diffs = time_for_diffs
+        self.total_time_for_all_diffs = total_time_for_all_diffs
+        self.type = test_failures.determine_result_type(failures)
 
 
 class SingleTestThread(threading.Thread):
@@ -157,14 +158,14 @@ class SingleTestThread(threading.Thread):
             driver.run_test(test_info.uri.strip(), test_info.timeout,
                             test_info.image_hash)
         end = time.time()
-        self._test_stats = process_output(self._port,
+        self._test_result = process_output(self._port,
             test_info, self._test_types, self._test_args,
             self._configuration, self._output_dir, crash, timeout, end - start,
             actual_checksum, output, error)
         driver.stop()
 
-    def get_test_stats(self):
-        return self._test_stats
+    def get_test_result(self):
+        return self._test_result
 
 
 class TestShellThread(threading.Thread):
@@ -201,7 +202,7 @@ class TestShellThread(threading.Thread):
         self._canceled = False
         self._exception_info = None
         self._directory_timing_stats = {}
-        self._test_stats = []
+        self._test_results = []
         self._num_tests = 0
         self._start_time = 0
         self._stop_time = 0
@@ -218,10 +219,13 @@ class TestShellThread(threading.Thread):
         (number of tests in that directory, time to run the tests)"""
         return self._directory_timing_stats
 
-    def get_individual_test_stats(self):
-        """Returns a list of (test_filename, time_to_run_test,
-        total_time_for_all_diffs, time_for_diffs) tuples."""
-        return self._test_stats
+    def get_test_results(self):
+        """Return the list of all tests run on this thread.
+
+        This is used to calculate per-thread statistics.
+
+        """
+        return self._test_results
 
     def cancel(self):
         """Set a flag telling this thread to quit."""
@@ -317,27 +321,29 @@ class TestShellThread(threading.Thread):
             batch_count += 1
             self._num_tests += 1
             if self._options.run_singly:
-                failures = self._run_test_singly(test_info)
+                result = self._run_test_singly(test_info)
             else:
-                failures = self._run_test(test_info)
+                result = self._run_test(test_info)
 
             filename = test_info.filename
             tests_run_file.write(filename + "\n")
-            if failures:
-                # Check and kill DumpRenderTree if we need too.
-                if len([1 for f in failures if f.should_kill_dump_render_tree()]):
+            if result.failures:
+                # Check and kill DumpRenderTree if we need to.
+                if len([1 for f in result.failures
+                        if f.should_kill_dump_render_tree()]):
                     self._kill_dump_render_tree()
                     # Reset the batch count since the shell just bounced.
                     batch_count = 0
                 # Print the error message(s).
-                error_str = '\n'.join(['  ' + f.message() for f in failures])
+                error_str = '\n'.join(['  ' + f.message() for
+                                       f in result.failures])
                 _log.debug("%s %s failed:\n%s" % (self.getName(),
                            self._port.relative_test_filename(filename),
                            error_str))
             else:
                 _log.debug("%s %s passed" % (self.getName(),
                            self._port.relative_test_filename(filename)))
-            self._result_queue.put((filename, failures))
+            self._result_queue.put(result)
 
             if batch_size > 0 and batch_count > batch_size:
                 # Bounce the shell and reset count.
@@ -357,8 +363,9 @@ class TestShellThread(threading.Thread):
         Args:
           test_info: Object containing the test filename, uri and timeout
 
-        Return:
-          A list of TestFailure objects describing the error.
+        Returns:
+          A TestResult
+
         """
         worker = SingleTestThread(self._port, self._image_path,
                                   self._shell_args,
@@ -370,9 +377,9 @@ class TestShellThread(threading.Thread):
 
         worker.start()
 
-        # When we're running one test per DumpRenderTree process, we can enforce
-        # a hard timeout. the DumpRenderTree watchdog uses 2.5x the timeout
-        # We want to be larger than that.
+        # When we're running one test per DumpRenderTree process, we can
+        # enforce a hard timeout.  The DumpRenderTree watchdog uses 2.5x
+        # the timeout; we want to be larger than that.
         worker.join(int(test_info.timeout) * 3.0 / 1000.0)
         if worker.isAlive():
             # If join() returned with the thread still running, the
@@ -380,22 +387,23 @@ class TestShellThread(threading.Thread):
             # more we can do with it.  We have to kill all the
             # DumpRenderTrees to free it up. If we're running more than
             # one DumpRenderTree thread, we'll end up killing the other
-            # DumpRenderTrees too, introducing spurious crashes. We accept that
-            # tradeoff in order to avoid losing the rest of this thread's
-            # results.
+            # DumpRenderTrees too, introducing spurious crashes. We accept
+            # that tradeoff in order to avoid losing the rest of this
+            # thread's results.
             _log.error('Test thread hung: killing all DumpRenderTrees')
             worker._driver.stop()
 
         try:
-            stats = worker.get_test_stats()
-            self._test_stats.append(stats)
-            failures = stats.failures
+            result = worker.get_test_result()
         except AttributeError, e:
             failures = []
             _log.error('Cannot get results of test: %s' %
                        test_info.filename)
+            result = TestResult(test_info.filename, failures=[],
+                                test_run_time=0, total_time_for_all_diffs=0,
+                                time_for_diffs=0)
 
-        return failures
+        return result
 
     def _run_test(self, test_info):
         """Run a single test file using a shared DumpRenderTree process.
@@ -403,8 +411,9 @@ class TestShellThread(threading.Thread):
         Args:
           test_info: Object containing the test filename, uri and timeout
 
-        Return:
+        Returns:
           A list of TestFailure objects describing the error.
+
         """
         self._ensure_dump_render_tree_is_running()
         # The pixel_hash is used to avoid doing an image dump if the
@@ -419,19 +428,20 @@ class TestShellThread(threading.Thread):
            self._driver.run_test(test_info.uri, test_info.timeout, image_hash)
         end = time.time()
 
-        stats = process_output(self._port, test_info, self._test_types,
-                               self._test_args, self._options.configuration,
-                               self._options.results_directory, crash,
-                               timeout, end - start, actual_checksum,
-                               output, error)
-
-        self._test_stats.append(stats)
-        return stats.failures
+        result = process_output(self._port, test_info, self._test_types,
+                                self._test_args, self._options.configuration,
+                                self._options.results_directory, crash,
+                                timeout, end - start, actual_checksum,
+                                output, error)
+        self._test_results.append(result)
+        return result
 
     def _ensure_dump_render_tree_is_running(self):
-        """Start the shared DumpRenderTree, if it's not running.  Not for use when
-        running tests singly, since those each start a separate DumpRenderTree in
-        their own thread.
+        """Start the shared DumpRenderTree, if it's not running.
+
+        This is not for use when running tests singly, since those each start
+        a separate DumpRenderTree in their own thread.
+
         """
         if (not self._driver or self._driver.poll() is not None):
             self._driver = self._port.start_driver(
index 397ec6e..38223dd 100644 (file)
@@ -48,6 +48,7 @@ _log = logging.getLogger("webkitpy.layout_tests.layout_package."
 # Test expectation file update action constants
 (NO_CHANGE, REMOVE_TEST, REMOVE_PLATFORM, ADD_PLATFORMS_EXCEPT_THIS) = range(4)
 
+
 def result_was_expected(result, expected_results, test_needs_rebaselining,
                         test_is_skipped):
     """Returns whether we got a result we were expecting.
@@ -61,11 +62,12 @@ def result_was_expected(result, expected_results, test_needs_rebaselining,
     if result in (IMAGE, TEXT, IMAGE_PLUS_TEXT) and FAIL in expected_results:
         return True
     if result == MISSING and test_needs_rebaselining:
-       return True
+        return True
     if result == SKIP and test_is_skipped:
-       return True
+        return True
     return False
 
+
 def remove_pixel_failures(expected_results):
     """Returns a copy of the expected results for a test, except that we
     drop any pixel failures and return the remaining expectations. For example,
@@ -141,12 +143,16 @@ class TestExpectations:
         retval = []
 
         for expectation in expectations:
-            for item in TestExpectationsFile.EXPECTATIONS.items():
-                if item[1] == expectation:
-                    retval.append(item[0])
-                    break
+            retval.append(self.expectation_to_string(expectation))
+
+        return " ".join(retval)
 
-        return " ".join(retval).upper()
+    def expectation_to_string(self, expectation):
+        """Return the uppercased string equivalent of a given expectation."""
+        for item in TestExpectationsFile.EXPECTATIONS.items():
+            if item[1] == expectation:
+                return item[0].upper()
+        return ""
 
     def get_timeline_for_test(self, test):
         return self._expected_failures.get_timeline_for_test(test)
@@ -834,7 +840,8 @@ class TestExpectationsFile:
             if test in set_of_tests:
                 set_of_tests.remove(test)
 
-    def _already_seen_test(self, test, test_list_path, lineno, allow_overrides):
+    def _already_seen_test(self, test, test_list_path, lineno,
+                           allow_overrides):
         """Returns true if we've already seen a more precise path for this test
         than the test_list_path.
         """
index 765829b..1be87ae 100755 (executable)
@@ -90,10 +90,12 @@ LOG_DETAILED_PROGRESS = 'detailed-progress'
 # Log the one-line summary at the end of the run
 LOG_SUMMARY = 'summary'
 
+# "Trace" the test - log the expected result, the actual result, and the
+# baselines used
+LOG_TRACE = 'trace'
+
 # Log any unexpected results while running (instead of just at the end).
 LOG_UNEXPECTED = 'unexpected'
-
-# Log any unexpected results at the end
 LOG_UNEXPECTED_RESULTS = 'unexpected-results'
 
 LOG_VALUES = ",".join(("actual", "config", LOG_DETAILED_PROGRESS, "expected",
@@ -153,25 +155,23 @@ class ResultSummary(object):
             self.tests_by_timeline[timeline] = (
                 expectations.get_tests_with_timeline(timeline))
 
-    def add(self, test, failures, result, expected):
-        """Add a result into the appropriate bin.
+    def add(self, result, expected):
+        """Add a TestResult into the appropriate bin.
 
         Args:
-          test: test file name
-          failures: list of failure objects from test execution
-          result: result of test (PASS, IMAGE, etc.).
+          result: TestResult from dump_render_tree_thread.
           expected: whether the result was what we expected it to be.
         """
 
-        self.tests_by_expectation[result].add(test)
-        self.results[test] = result
+        self.tests_by_expectation[result.type].add(result.filename)
+        self.results[result.filename] = result.type
         self.remaining -= 1
-        if len(failures):
-            self.failures[test] = failures
+        if len(result.failures):
+            self.failures[result.filename] = result.failures
         if expected:
             self.expected += 1
         else:
-            self.unexpected_results[test] = result
+            self.unexpected_results[result.filename] = result.type
             self.unexpected += 1
 
 
@@ -394,8 +394,11 @@ class TestRunner:
             # subtracted out of self._test_files, above), but we stub out the
             # results here so the statistics can remain accurate.
             for test in skip_chunk:
-                result_summary.add(test, [], test_expectations.SKIP,
-                                   expected=True)
+                result = dump_render_tree_thread.TestResult(test,
+                    failures=[], test_run_time=0, total_time_for_all_diffs=0,
+                    time_for_diffs=0)
+                result.type = test_expectations.SKIP
+                result_summary.add(result, expected=True)
         write("")
 
         return result_summary
@@ -602,7 +605,7 @@ class TestRunner:
                                        'total_time': thread.get_total_time()})
                 test_timings.update(thread.get_directory_timing_stats())
                 individual_test_timings.extend(
-                    thread.get_individual_test_stats())
+                    thread.get_test_results())
         except KeyboardInterrupt:
             for thread in threads:
                 thread.cancel()
@@ -719,27 +722,58 @@ class TestRunner:
         return unexpected_results['num_regressions']
 
     def update_summary(self, result_summary):
-        """Update the summary while running tests."""
+        """Update the summary and print results with any completed tests."""
         while True:
             try:
-                (test, fail_list) = self._result_queue.get_nowait()
-                result = test_failures.determine_result_type(fail_list)
-                expected = self._expectations.matches_an_expected_result(test,
-                    result, self._options.pixel_tests)
-                result_summary.add(test, fail_list, result, expected)
-                if (LOG_DETAILED_PROGRESS in self._options.log and
-                    (self._options.experimental_fully_parallel or
-                     self._is_single_threaded())):
-                    self._display_detailed_progress(result_summary)
-                else:
-                    if not expected and LOG_UNEXPECTED in self._options.log:
-                        self._print_unexpected_test_result(test, result)
-                    if LOG_PROGRESS in self._options.log:
-                        self._display_one_line_progress(result_summary)
+                result = self._result_queue.get_nowait()
             except Queue.Empty:
                 return
-
-    def _display_one_line_progress(self, result_summary):
+            expected = self._expectations.matches_an_expected_result(
+                result.filename, result.type, self._options.pixel_tests)
+            result_summary.add(result, expected)
+            self._print_test_results(result, expected, result_summary)
+
+    def _print_test_results(self, result, expected, result_summary):
+        "Print the result of the test as determined by the --log switches."
+        if LOG_TRACE in self._options.log:
+            self._print_test_trace(result)
+        elif (LOG_DETAILED_PROGRESS in self._options.log and
+              (self._options.experimental_fully_parallel or
+               self._is_single_threaded())):
+            self._print_detailed_progress(result_summary)
+        else:
+            if (not expected and LOG_UNEXPECTED in self._options.log):
+                self._print_unexpected_test_result(result)
+            self._print_one_line_progress(result_summary)
+
+    def _print_test_trace(self, result):
+        """Print detailed results of a test (triggered by --log trace).
+        For each test, print:
+           - location of the expected baselines
+           - expected results
+           - actual result
+           - timing info
+        """
+        filename = result.filename
+        test_name = self._port.relative_test_filename(filename)
+        _log.info('trace: %s' % test_name)
+        _log.info('  txt: %s' %
+                  self._port.relative_test_filename(
+                       self._port.expected_filename(filename, '.txt')))
+        png_file = self._port.expected_filename(filename, '.png')
+        if os.path.exists(png_file):
+            _log.info('  png: %s' %
+                      self._port.relative_test_filename(filename))
+        else:
+            _log.info('  png: <none>')
+        _log.info('  exp: %s' %
+                  self._expectations.get_expectations_string(filename))
+        _log.info('  got: %s' %
+                  self._expectations.expectation_to_string(result.type))
+        _log.info(' took: %-.3f' % result.test_run_time)
+        _log.info('')
+
+    def _print_one_line_progress(self, result_summary):
         """Displays the progress through the test run."""
         percent_complete = 100 * (result_summary.expected +
             result_summary.unexpected) / result_summary.total
@@ -750,7 +784,7 @@ class TestRunner:
             " %d left" % (action, percent_complete, result_summary.expected,
              result_summary.unexpected, result_summary.remaining))
 
-    def _display_detailed_progress(self, result_summary):
+    def _print_detailed_progress(self, result_summary):
         """Display detailed progress output where we print the directory name
         and one dot for each completed test. This is triggered by
         "--log detailed-progress"."""
@@ -794,6 +828,13 @@ class TestRunner:
         else:
             self._meter.progress("%s\n" % (self._current_progress_str))
 
+    def _print_unexpected_test_result(self, result):
+        """Prints one unexpected test result line."""
+        desc = TestExpectationsFile.EXPECTATION_DESCRIPTIONS[result.type][0]
+        self._meter.write("  %s -> unexpected %s\n" %
+                          (self._port.relative_test_filename(result.filename),
+                           desc))
+
     def _get_failures(self, result_summary, include_crashes):
         """Filters a dict of results and returns only the failures.
 
@@ -1307,12 +1348,6 @@ class TestRunner:
         if len(unexpected_results['tests']) and self._options.verbose:
             print "-" * 78
 
-    def _print_unexpected_test_result(self, test, result):
-        """Prints one unexpected test result line."""
-        desc = TestExpectationsFile.EXPECTATION_DESCRIPTIONS[result][0]
-        self._meter.write("  %s -> unexpected %s\n" %
-                          (self._port.relative_test_filename(test), desc))
-
     def _write_results_html_file(self, result_summary):
         """Write results.html which is a summary of tests that failed.