diff options
Diffstat (limited to 'Tools/Scripts/webkitpy/layout_tests/layout_package/printing.py')
| -rw-r--r-- | Tools/Scripts/webkitpy/layout_tests/layout_package/printing.py | 553 |
1 files changed, 553 insertions, 0 deletions
diff --git a/Tools/Scripts/webkitpy/layout_tests/layout_package/printing.py b/Tools/Scripts/webkitpy/layout_tests/layout_package/printing.py new file mode 100644 index 0000000..7a6aad1 --- /dev/null +++ b/Tools/Scripts/webkitpy/layout_tests/layout_package/printing.py @@ -0,0 +1,553 @@ +#!/usr/bin/env python +# Copyright (C) 2010 Google Inc. All rights reserved. +# +# Redistribution and use in source and binary forms, with or without +# modification, are permitted provided that the following conditions are +# met: +# +# * Redistributions of source code must retain the above copyright +# notice, this list of conditions and the following disclaimer. +# * Redistributions in binary form must reproduce the above +# copyright notice, this list of conditions and the following disclaimer +# in the documentation and/or other materials provided with the +# distribution. +# * Neither the name of Google Inc. nor the names of its +# contributors may be used to endorse or promote products derived from +# this software without specific prior written permission. +# +# THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS +# "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT +# LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR +# A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT +# OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, +# SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT +# LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, +# DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY +# THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT +# (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE +# OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. + +"""Package that handles non-debug, non-file output for run-webkit-tests.""" + +import logging +import optparse +import os +import pdb + +from webkitpy.layout_tests.layout_package import metered_stream +from webkitpy.layout_tests.layout_package import test_expectations + +_log = logging.getLogger("webkitpy.layout_tests.printer") + +TestExpectationsFile = test_expectations.TestExpectationsFile + +NUM_SLOW_TESTS_TO_LOG = 10 + +PRINT_DEFAULT = ("misc,one-line-progress,one-line-summary,unexpected," + "unexpected-results,updates") +PRINT_EVERYTHING = ("actual,config,expected,misc,one-line-progress," + "one-line-summary,slowest,timing,unexpected," + "unexpected-results,updates") + +HELP_PRINTING = """ +Output for run-webkit-tests is controlled by a comma-separated list of +values passed to --print. Values either influence the overall output, or +the output at the beginning of the run, during the run, or at the end: + +Overall options: + nothing don't print anything. This overrides every other option + default include the default options. This is useful for logging + the default options plus additional settings. + everything print everything (except the trace-* options and the + detailed-progress option, see below for the full list ) + misc print miscellaneous things like blank lines + +At the beginning of the run: + config print the test run configuration + expected print a summary of what is expected to happen + (# passes, # failures, etc.) + +During the run: + detailed-progress print one dot per test completed + one-line-progress print a one-line progress bar + unexpected print any unexpected results as they occur + updates print updates on which stage is executing + trace-everything print detailed info on every test's results + (baselines, expectation, time it took to run). If + this is specified it will override the '*-progress' + options, the 'trace-unexpected' option, and the + 'unexpected' option. + trace-unexpected like 'trace-everything', but only for tests with + unexpected results. If this option is specified, + it will override the 'unexpected' option. + +At the end of the run: + actual print a summary of the actual results + slowest print %(slowest)d slowest tests and the time they took + timing print timing statistics + unexpected-results print a list of the tests with unexpected results + one-line-summary print a one-line summary of the run + +Notes: + - 'detailed-progress' can only be used if running in a single thread + (using --child-processes=1) or a single queue of tests (using + --experimental-fully-parallel). If these conditions aren't true, + 'one-line-progress' will be used instead. + - If both 'detailed-progress' and 'one-line-progress' are specified (and + both are possible), 'detailed-progress' will be used. + - If 'nothing' is specified, it overrides all of the other options. + - Specifying --verbose is equivalent to --print everything plus it + changes the format of the log messages to add timestamps and other + information. If you specify --verbose and --print X, then X overrides + the --print everything implied by --verbose. + +--print 'everything' is equivalent to --print '%(everything)s'. + +The default (--print default) is equivalent to --print '%(default)s'. +""" % {'slowest': NUM_SLOW_TESTS_TO_LOG, 'everything': PRINT_EVERYTHING, + 'default': PRINT_DEFAULT} + + +def print_options(): + return [ + # Note: We use print_options rather than just 'print' because print + # is a reserved word. + # Note: Also, we don't specify a default value so we can detect when + # no flag is specified on the command line and use different defaults + # based on whether or not --verbose is specified (since --print + # overrides --verbose). + optparse.make_option("--print", dest="print_options", + help=("controls print output of test run. " + "Use --help-printing for more.")), + optparse.make_option("--help-printing", action="store_true", + help="show detailed help on controlling print output"), + optparse.make_option("-v", "--verbose", action="store_true", + default=False, help="include debug-level logging"), + ] + + +def parse_print_options(print_options, verbose, child_processes, + is_fully_parallel): + """Parse the options provided to --print and dedup and rank them. + + Returns + a set() of switches that govern how logging is done + + """ + if print_options: + switches = set(print_options.split(',')) + elif verbose: + switches = set(PRINT_EVERYTHING.split(',')) + else: + switches = set(PRINT_DEFAULT.split(',')) + + if 'nothing' in switches: + return set() + + if (child_processes != 1 and not is_fully_parallel and + 'detailed-progress' in switches): + _log.warn("Can only print 'detailed-progress' if running " + "with --child-processes=1 or " + "with --experimental-fully-parallel. " + "Using 'one-line-progress' instead.") + switches.discard('detailed-progress') + switches.add('one-line-progress') + + if 'everything' in switches: + switches.discard('everything') + switches.update(set(PRINT_EVERYTHING.split(','))) + + if 'default' in switches: + switches.discard('default') + switches.update(set(PRINT_DEFAULT.split(','))) + + if 'detailed-progress' in switches: + switches.discard('one-line-progress') + + if 'trace-everything' in switches: + switches.discard('detailed-progress') + switches.discard('one-line-progress') + switches.discard('trace-unexpected') + switches.discard('unexpected') + + if 'trace-unexpected' in switches: + switches.discard('unexpected') + + return switches + + +def _configure_logging(stream, verbose): + log_fmt = '%(message)s' + log_datefmt = '%y%m%d %H:%M:%S' + log_level = logging.INFO + if verbose: + log_fmt = ('%(asctime)s %(process)d %(filename)s:%(lineno)d ' + '%(levelname)s %(message)s') + log_level = logging.DEBUG + + root = logging.getLogger() + handler = logging.StreamHandler(stream) + handler.setFormatter(logging.Formatter(log_fmt, None)) + root.addHandler(handler) + root.setLevel(log_level) + return handler + + +def _restore_logging(handler_to_remove): + root = logging.getLogger() + root.handlers.remove(handler_to_remove) + + +class Printer(object): + """Class handling all non-debug-logging printing done by run-webkit-tests. + + Printing from run-webkit-tests falls into two buckets: general or + regular output that is read only by humans and can be changed at any + time, and output that is parsed by buildbots (and humans) and hence + must be changed more carefully and in coordination with the buildbot + parsing code (in chromium.org's buildbot/master.chromium/scripts/master/ + log_parser/webkit_test_command.py script). + + By default the buildbot-parsed code gets logged to stdout, and regular + output gets logged to stderr.""" + def __init__(self, port, options, regular_output, buildbot_output, + child_processes, is_fully_parallel): + """ + Args + port interface to port-specific routines + options OptionParser object with command line settings + regular_output stream to which output intended only for humans + should be written + buildbot_output stream to which output intended to be read by + the buildbots (and humans) should be written + child_processes number of parallel threads running (usually + controlled by --child-processes) + is_fully_parallel are the tests running in a single queue, or + in shards (usually controlled by + --experimental-fully-parallel) + + Note that the last two args are separate rather than bundled into + the options structure so that this object does not assume any flags + set in options that weren't returned from logging_options(), above. + The two are used to determine whether or not we can sensibly use + the 'detailed-progress' option, or can only use 'one-line-progress'. + """ + self._buildbot_stream = buildbot_output + self._options = options + self._port = port + self._stream = regular_output + + # These are used for --print detailed-progress to track status by + # directory. + self._current_dir = None + self._current_progress_str = "" + self._current_test_number = 0 + + self._meter = metered_stream.MeteredStream(options.verbose, + regular_output) + self._logging_handler = _configure_logging(self._meter, + options.verbose) + + self.switches = parse_print_options(options.print_options, + options.verbose, child_processes, is_fully_parallel) + + def cleanup(self): + """Restore logging configuration to its initial settings.""" + if self._logging_handler: + _restore_logging(self._logging_handler) + self._logging_handler = None + + def __del__(self): + self.cleanup() + + # These two routines just hide the implementation of the switches. + def disabled(self, option): + return not option in self.switches + + def enabled(self, option): + return option in self.switches + + def help_printing(self): + self._write(HELP_PRINTING) + + def print_actual(self, msg): + if self.disabled('actual'): + return + self._buildbot_stream.write("%s\n" % msg) + + def print_config(self, msg): + self.write(msg, 'config') + + def print_expected(self, msg): + self.write(msg, 'expected') + + def print_timing(self, msg): + self.write(msg, 'timing') + + def print_one_line_summary(self, total, expected, unexpected): + """Print a one-line summary of the test run to stdout. + + Args: + total: total number of tests run + expected: number of expected results + unexpected: number of unexpected results + """ + if self.disabled('one-line-summary'): + return + + incomplete = total - expected - unexpected + if incomplete: + self._write("") + incomplete_str = " (%d didn't run)" % incomplete + expected_str = str(expected) + else: + incomplete_str = "" + expected_str = "All %d" % expected + + if unexpected == 0: + self._write("%s tests ran as expected%s." % + (expected_str, incomplete_str)) + elif expected == 1: + self._write("1 test ran as expected, %d didn't%s:" % + (unexpected, incomplete_str)) + else: + self._write("%d tests ran as expected, %d didn't%s:" % + (expected, unexpected, incomplete_str)) + self._write("") + + def print_test_result(self, result, expected, exp_str, got_str): + """Print the result of the test as determined by --print. + + This routine is used to print the details of each test as it completes. + + Args: + result - The actual TestResult object + expected - Whether the result we got was an expected result + exp_str - What we expected to get (used for tracing) + got_str - What we actually got (used for tracing) + + Note that we need all of these arguments even though they seem + somewhat redundant, in order to keep this routine from having to + known anything about the set of expectations. + """ + if (self.enabled('trace-everything') or + self.enabled('trace-unexpected') and not expected): + self._print_test_trace(result, exp_str, got_str) + elif (not expected and self.enabled('unexpected') and + self.disabled('detailed-progress')): + # Note: 'detailed-progress' handles unexpected results internally, + # so we skip it here. + self._print_unexpected_test_result(result) + + def _print_test_trace(self, result, exp_str, got_str): + """Print detailed results of a test (triggered by --print 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) + self._write('trace: %s' % test_name) + txt_file = self._port.expected_filename(filename, '.txt') + if self._port.path_exists(txt_file): + self._write(' txt: %s' % + self._port.relative_test_filename(txt_file)) + else: + self._write(' txt: <none>') + checksum_file = self._port.expected_filename(filename, '.checksum') + if self._port.path_exists(checksum_file): + self._write(' sum: %s' % + self._port.relative_test_filename(checksum_file)) + else: + self._write(' sum: <none>') + png_file = self._port.expected_filename(filename, '.png') + if self._port.path_exists(png_file): + self._write(' png: %s' % + self._port.relative_test_filename(png_file)) + else: + self._write(' png: <none>') + self._write(' exp: %s' % exp_str) + self._write(' got: %s' % got_str) + self._write(' took: %-.3f' % result.test_run_time) + self._write('') + + def _print_unexpected_test_result(self, result): + """Prints one unexpected test result line.""" + desc = TestExpectationsFile.EXPECTATION_DESCRIPTIONS[result.type][0] + self.write(" %s -> unexpected %s" % + (self._port.relative_test_filename(result.filename), + desc), "unexpected") + + def print_progress(self, result_summary, retrying, test_list): + """Print progress through the tests as determined by --print.""" + if self.enabled('detailed-progress'): + self._print_detailed_progress(result_summary, test_list) + elif self.enabled('one-line-progress'): + self._print_one_line_progress(result_summary, retrying) + else: + return + + if result_summary.remaining == 0: + self._meter.update('') + + def _print_one_line_progress(self, result_summary, retrying): + """Displays the progress through the test run.""" + percent_complete = 100 * (result_summary.expected + + result_summary.unexpected) / result_summary.total + action = "Testing" + if retrying: + action = "Retrying" + self._meter.progress("%s (%d%%): %d ran as expected, %d didn't," + " %d left" % (action, percent_complete, result_summary.expected, + result_summary.unexpected, result_summary.remaining)) + + def _print_detailed_progress(self, result_summary, test_list): + """Display detailed progress output where we print the directory name + and one dot for each completed test. This is triggered by + "--log detailed-progress".""" + if self._current_test_number == len(test_list): + return + + next_test = test_list[self._current_test_number] + next_dir = os.path.dirname( + self._port.relative_test_filename(next_test)) + if self._current_progress_str == "": + self._current_progress_str = "%s: " % (next_dir) + self._current_dir = next_dir + + while next_test in result_summary.results: + if next_dir != self._current_dir: + self._meter.write("%s\n" % (self._current_progress_str)) + self._current_progress_str = "%s: ." % (next_dir) + self._current_dir = next_dir + else: + self._current_progress_str += "." + + if (next_test in result_summary.unexpected_results and + self.enabled('unexpected')): + self._meter.write("%s\n" % self._current_progress_str) + test_result = result_summary.results[next_test] + self._print_unexpected_test_result(test_result) + self._current_progress_str = "%s: " % self._current_dir + + self._current_test_number += 1 + if self._current_test_number == len(test_list): + break + + next_test = test_list[self._current_test_number] + next_dir = os.path.dirname( + self._port.relative_test_filename(next_test)) + + if result_summary.remaining: + remain_str = " (%d)" % (result_summary.remaining) + self._meter.progress("%s%s" % (self._current_progress_str, + remain_str)) + else: + self._meter.progress("%s" % (self._current_progress_str)) + + def print_unexpected_results(self, unexpected_results): + """Prints a list of the unexpected results to the buildbot stream.""" + if self.disabled('unexpected-results'): + return + + passes = {} + flaky = {} + regressions = {} + + for test, results in unexpected_results['tests'].iteritems(): + actual = results['actual'].split(" ") + expected = results['expected'].split(" ") + if actual == ['PASS']: + if 'CRASH' in expected: + _add_to_dict_of_lists(passes, + 'Expected to crash, but passed', + test) + elif 'TIMEOUT' in expected: + _add_to_dict_of_lists(passes, + 'Expected to timeout, but passed', + test) + else: + _add_to_dict_of_lists(passes, + 'Expected to fail, but passed', + test) + elif len(actual) > 1: + # We group flaky tests by the first actual result we got. + _add_to_dict_of_lists(flaky, actual[0], test) + else: + _add_to_dict_of_lists(regressions, results['actual'], test) + + if len(passes) or len(flaky) or len(regressions): + self._buildbot_stream.write("\n") + + if len(passes): + for key, tests in passes.iteritems(): + self._buildbot_stream.write("%s: (%d)\n" % (key, len(tests))) + tests.sort() + for test in tests: + self._buildbot_stream.write(" %s\n" % test) + self._buildbot_stream.write("\n") + self._buildbot_stream.write("\n") + + if len(flaky): + descriptions = TestExpectationsFile.EXPECTATION_DESCRIPTIONS + for key, tests in flaky.iteritems(): + result = TestExpectationsFile.EXPECTATIONS[key.lower()] + self._buildbot_stream.write("Unexpected flakiness: %s (%d)\n" + % (descriptions[result][1], len(tests))) + tests.sort() + + for test in tests: + result = unexpected_results['tests'][test] + actual = result['actual'].split(" ") + expected = result['expected'].split(" ") + result = TestExpectationsFile.EXPECTATIONS[key.lower()] + new_expectations_list = list(set(actual) | set(expected)) + self._buildbot_stream.write(" %s = %s\n" % + (test, " ".join(new_expectations_list))) + self._buildbot_stream.write("\n") + self._buildbot_stream.write("\n") + + if len(regressions): + descriptions = TestExpectationsFile.EXPECTATION_DESCRIPTIONS + for key, tests in regressions.iteritems(): + result = TestExpectationsFile.EXPECTATIONS[key.lower()] + self._buildbot_stream.write( + "Regressions: Unexpected %s : (%d)\n" % ( + descriptions[result][1], len(tests))) + tests.sort() + for test in tests: + self._buildbot_stream.write(" %s = %s\n" % (test, key)) + self._buildbot_stream.write("\n") + self._buildbot_stream.write("\n") + + if len(unexpected_results['tests']) and self._options.verbose: + self._buildbot_stream.write("%s\n" % ("-" * 78)) + + def print_update(self, msg): + if self.disabled('updates'): + return + self._meter.update(msg) + + def write(self, msg, option="misc"): + if self.disabled(option): + return + self._write(msg) + + def _write(self, msg): + # FIXME: we could probably get away with calling _log.info() all of + # the time, but there doesn't seem to be a good way to test the output + # from the logger :(. + if self._options.verbose: + _log.info(msg) + else: + self._meter.write("%s\n" % msg) + +# +# Utility routines used by the Controller class +# + + +def _add_to_dict_of_lists(dict, key, value): + dict.setdefault(key, []).append(value) |