1 # Copyright (C) 2010, 2012 Google Inc. All rights reserved. 2 # 3 # Redistribution and use in source and binary forms, with or without 4 # modification, are permitted provided that the following conditions are 5 # met: 6 # 7 # * Redistributions of source code must retain the above copyright 8 # notice, this list of conditions and the following disclaimer. 9 # * Redistributions in binary form must reproduce the above 10 # copyright notice, this list of conditions and the following disclaimer 11 # in the documentation and/or other materials provided with the 12 # distribution. 13 # * Neither the name of Google Inc. nor the names of its 14 # contributors may be used to endorse or promote products derived from 15 # this software without specific prior written permission. 16 # 17 # THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS 18 # "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT 19 # LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR 20 # A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT 21 # OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, 22 # SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT 23 # LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, 24 # DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY 25 # THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT 26 # (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE 27 # OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. 28 29 """Package that handles non-debug, non-file output for run-webkit-tests.""" 30 31 import math 32 import optparse 33 34 from webkitpy.tool import grammar 35 from webkitpy.layout_tests.models import test_expectations 36 from webkitpy.layout_tests.models.test_expectations import TestExpectations, TestExpectationParser 37 from webkitpy.layout_tests.views.metered_stream import MeteredStream 38 39 40 NUM_SLOW_TESTS_TO_LOG = 10 41 42 43 def print_options(): 44 return [ 45 optparse.make_option('--debug-rwt-logging', action='store_true', default=False, 46 help='print timestamps and debug information for run-webkit-tests itself'), 47 optparse.make_option('--details', action='store_true', default=False, 48 help='print detailed results for every test'), 49 optparse.make_option('-q', '--quiet', action='store_true', default=False, 50 help='run quietly (errors, warnings, and progress only)'), 51 optparse.make_option('--timing', action='store_true', default=False, 52 help='display test times (summary plus per-test w/ --verbose)'), 53 optparse.make_option('-v', '--verbose', action='store_true', default=False, 54 help='print a summarized result for every test (one line per test)'), 55 ] 56 57 58 class Printer(object): 59 """Class handling all non-debug-logging printing done by run-webkit-tests.""" 60 61 def __init__(self, port, options, regular_output, logger=None): 62 self.num_completed = 0 63 self.num_tests = 0 64 self._port = port 65 self._options = options 66 self._meter = MeteredStream(regular_output, options.debug_rwt_logging, logger=logger, 67 number_of_columns=self._port.host.platform.terminal_width()) 68 self._running_tests = [] 69 self._completed_tests = [] 70 71 def cleanup(self): 72 self._meter.cleanup() 73 74 def __del__(self): 75 self.cleanup() 76 77 def print_config(self, results_directory): 78 self._print_default("Using port '%s'" % self._port.name()) 79 self._print_default("Test configuration: %s" % self._port.test_configuration()) 80 self._print_default("View the test results at file://%s/results.html" % results_directory) 81 self._print_default("View the archived results dashboard at file://%s/dashboard.html" % results_directory) 82 83 # FIXME: should these options be in printing_options? 84 if self._options.new_baseline: 85 self._print_default("Placing new baselines in %s" % self._port.baseline_path()) 86 87 fs = self._port.host.filesystem 88 fallback_path = [fs.split(x)[1] for x in self._port.baseline_search_path()] 89 self._print_default("Baseline search path: %s -> generic" % " -> ".join(fallback_path)) 90 91 self._print_default("Using %s build" % self._options.configuration) 92 if self._options.pixel_tests: 93 self._print_default("Pixel tests enabled") 94 else: 95 self._print_default("Pixel tests disabled") 96 97 self._print_default("Regular timeout: %s, slow test timeout: %s" % 98 (self._options.time_out_ms, self._options.slow_time_out_ms)) 99 100 self._print_default('Command line: ' + ' '.join(self._port.driver_cmd_line())) 101 self._print_default('') 102 103 def print_found(self, num_all_test_files, num_to_run, repeat_each, iterations): 104 found_str = 'Found %s; running %d' % (grammar.pluralize('test', num_all_test_files), num_to_run) 105 if repeat_each * iterations > 1: 106 found_str += ' (%d times each: --repeat-each=%d --iterations=%d)' % (repeat_each * iterations, repeat_each, iterations) 107 found_str += ', skipping %d' % (num_all_test_files - num_to_run) 108 self._print_default(found_str + '.') 109 110 def print_expected(self, run_results, tests_with_result_type_callback): 111 self._print_expected_results_of_type(run_results, test_expectations.PASS, "passes", tests_with_result_type_callback) 112 self._print_expected_results_of_type(run_results, test_expectations.FAIL, "failures", tests_with_result_type_callback) 113 self._print_expected_results_of_type(run_results, test_expectations.FLAKY, "flaky", tests_with_result_type_callback) 114 self._print_debug('') 115 116 def print_workers_and_shards(self, num_workers, num_shards, num_locked_shards): 117 driver_name = self._port.driver_name() 118 if num_workers == 1: 119 self._print_default("Running 1 %s." % driver_name) 120 self._print_debug("(%s)." % grammar.pluralize('shard', num_shards)) 121 else: 122 self._print_default("Running %d %ss in parallel." % (num_workers, driver_name)) 123 self._print_debug("(%d shards; %d locked)." % (num_shards, num_locked_shards)) 124 self._print_default('') 125 126 def _print_expected_results_of_type(self, run_results, result_type, result_type_str, tests_with_result_type_callback): 127 tests = tests_with_result_type_callback(result_type) 128 now = run_results.tests_by_timeline[test_expectations.NOW] 129 wontfix = run_results.tests_by_timeline[test_expectations.WONTFIX] 130 131 # We use a fancy format string in order to print the data out in a 132 # nicely-aligned table. 133 fmtstr = ("Expect: %%5d %%-8s (%%%dd now, %%%dd wontfix)" 134 % (self._num_digits(now), self._num_digits(wontfix))) 135 self._print_debug(fmtstr % (len(tests), result_type_str, len(tests & now), len(tests & wontfix))) 136 137 def _num_digits(self, num): 138 ndigits = 1 139 if len(num): 140 ndigits = int(math.log10(len(num))) + 1 141 return ndigits 142 143 def print_results(self, run_time, run_results, summarized_results): 144 self._print_timing_statistics(run_time, run_results) 145 self._print_one_line_summary(run_time, run_results) 146 147 def _print_timing_statistics(self, total_time, run_results): 148 self._print_debug("Test timing:") 149 self._print_debug(" %6.2f total testing time" % total_time) 150 self._print_debug("") 151 152 self._print_worker_statistics(run_results, int(self._options.child_processes)) 153 self._print_aggregate_test_statistics(run_results) 154 self._print_individual_test_times(run_results) 155 self._print_directory_timings(run_results) 156 157 def _print_worker_statistics(self, run_results, num_workers): 158 self._print_debug("Thread timing:") 159 stats = {} 160 cuml_time = 0 161 for result in run_results.results_by_name.values(): 162 stats.setdefault(result.worker_name, {'num_tests': 0, 'total_time': 0}) 163 stats[result.worker_name]['num_tests'] += 1 164 stats[result.worker_name]['total_time'] += result.total_run_time 165 cuml_time += result.total_run_time 166 167 for worker_name in stats: 168 self._print_debug(" %10s: %5d tests, %6.2f secs" % (worker_name, stats[worker_name]['num_tests'], stats[worker_name]['total_time'])) 169 self._print_debug(" %6.2f cumulative, %6.2f optimal" % (cuml_time, cuml_time / num_workers)) 170 self._print_debug("") 171 172 def _print_aggregate_test_statistics(self, run_results): 173 times_for_dump_render_tree = [result.test_run_time for result in run_results.results_by_name.values()] 174 self._print_statistics_for_test_timings("PER TEST TIME IN TESTSHELL (seconds):", times_for_dump_render_tree) 175 176 def _print_individual_test_times(self, run_results): 177 # Reverse-sort by the time spent in the driver. 178 179 individual_test_timings = sorted(run_results.results_by_name.values(), key=lambda result: result.test_run_time, reverse=True) 180 num_printed = 0 181 slow_tests = [] 182 timeout_or_crash_tests = [] 183 unexpected_slow_tests = [] 184 for test_tuple in individual_test_timings: 185 test_name = test_tuple.test_name 186 is_timeout_crash_or_slow = False 187 if test_name in run_results.slow_tests: 188 is_timeout_crash_or_slow = True 189 slow_tests.append(test_tuple) 190 191 if test_name in run_results.failures_by_name: 192 result = run_results.results_by_name[test_name].type 193 if (result == test_expectations.TIMEOUT or 194 result == test_expectations.CRASH): 195 is_timeout_crash_or_slow = True 196 timeout_or_crash_tests.append(test_tuple) 197 198 if (not is_timeout_crash_or_slow and num_printed < NUM_SLOW_TESTS_TO_LOG): 199 num_printed = num_printed + 1 200 unexpected_slow_tests.append(test_tuple) 201 202 self._print_debug("") 203 if unexpected_slow_tests: 204 self._print_test_list_timing("%s slowest tests that are not marked as SLOW and did not timeout/crash:" % 205 NUM_SLOW_TESTS_TO_LOG, unexpected_slow_tests) 206 self._print_debug("") 207 208 if slow_tests: 209 self._print_test_list_timing("Tests marked as SLOW:", slow_tests) 210 self._print_debug("") 211 212 if timeout_or_crash_tests: 213 self._print_test_list_timing("Tests that timed out or crashed:", timeout_or_crash_tests) 214 self._print_debug("") 215 216 def _print_test_list_timing(self, title, test_list): 217 self._print_debug(title) 218 for test_tuple in test_list: 219 test_run_time = round(test_tuple.test_run_time, 1) 220 self._print_debug(" %s took %s seconds" % (test_tuple.test_name, test_run_time)) 221 222 def _print_directory_timings(self, run_results): 223 stats = {} 224 for result in run_results.results_by_name.values(): 225 stats.setdefault(result.shard_name, {'num_tests': 0, 'total_time': 0}) 226 stats[result.shard_name]['num_tests'] += 1 227 stats[result.shard_name]['total_time'] += result.total_run_time 228 229 min_seconds_to_print = 15 230 231 timings = [] 232 for directory in stats: 233 rounded_time = round(stats[directory]['total_time'], 1) 234 if rounded_time > min_seconds_to_print: 235 timings.append((directory, rounded_time, stats[directory]['num_tests'])) 236 237 if not timings: 238 return 239 240 timings.sort() 241 242 self._print_debug("Time to process slowest subdirectories:") 243 for timing in timings: 244 self._print_debug(" %s took %s seconds to run %s tests." % timing) 245 self._print_debug("") 246 247 def _print_statistics_for_test_timings(self, title, timings): 248 self._print_debug(title) 249 timings.sort() 250 251 num_tests = len(timings) 252 if not num_tests: 253 return 254 percentile90 = timings[int(.9 * num_tests)] 255 percentile99 = timings[int(.99 * num_tests)] 256 257 if num_tests % 2 == 1: 258 median = timings[((num_tests - 1) / 2) - 1] 259 else: 260 lower = timings[num_tests / 2 - 1] 261 upper = timings[num_tests / 2] 262 median = (float(lower + upper)) / 2 263 264 mean = sum(timings) / num_tests 265 266 for timing in timings: 267 sum_of_deviations = math.pow(timing - mean, 2) 268 269 std_deviation = math.sqrt(sum_of_deviations / num_tests) 270 self._print_debug(" Median: %6.3f" % median) 271 self._print_debug(" Mean: %6.3f" % mean) 272 self._print_debug(" 90th percentile: %6.3f" % percentile90) 273 self._print_debug(" 99th percentile: %6.3f" % percentile99) 274 self._print_debug(" Standard dev: %6.3f" % std_deviation) 275 self._print_debug("") 276 277 def _print_one_line_summary(self, total_time, run_results): 278 if self._options.timing: 279 parallel_time = sum(result.total_run_time for result in run_results.results_by_name.values()) 280 281 # There is serial overhead in layout_test_runner.run() that we can't easily account for when 282 # really running in parallel, but taking the min() ensures that in the worst case 283 # (if parallel time is less than run_time) we do account for it. 284 serial_time = total_time - min(run_results.run_time, parallel_time) 285 286 speedup = (parallel_time + serial_time) / total_time 287 timing_summary = ' in %.2fs (%.2fs in rwt, %.2gx)' % (total_time, serial_time, speedup) 288 else: 289 timing_summary = '' 290 291 total = run_results.total - run_results.expected_skips 292 expected = run_results.expected - run_results.expected_skips 293 unexpected = run_results.unexpected 294 incomplete = total - expected - unexpected 295 incomplete_str = '' 296 if incomplete: 297 self._print_default("") 298 incomplete_str = " (%d didn't run)" % incomplete 299 300 if self._options.verbose or self._options.debug_rwt_logging or unexpected: 301 self.writeln("") 302 303 expected_summary_str = '' 304 if run_results.expected_failures > 0: 305 expected_summary_str = " (%d passed, %d didn't)" % (expected - run_results.expected_failures, run_results.expected_failures) 306 307 summary = '' 308 if unexpected == 0: 309 if expected == total: 310 if expected > 1: 311 summary = "All %d tests ran as expected%s%s." % (expected, expected_summary_str, timing_summary) 312 else: 313 summary = "The test ran as expected%s%s." % (expected_summary_str, timing_summary) 314 else: 315 summary = "%s ran as expected%s%s%s." % (grammar.pluralize('test', expected), expected_summary_str, incomplete_str, timing_summary) 316 else: 317 summary = "%s ran as expected%s, %d didn't%s%s:" % (grammar.pluralize('test', expected), expected_summary_str, unexpected, incomplete_str, timing_summary) 318 319 self._print_quiet(summary) 320 self._print_quiet("") 321 322 def _test_status_line(self, test_name, suffix): 323 format_string = '[%d/%d] %s%s' 324 status_line = format_string % (self.num_completed, self.num_tests, test_name, suffix) 325 if len(status_line) > self._meter.number_of_columns(): 326 overflow_columns = len(status_line) - self._meter.number_of_columns() 327 ellipsis = '...' 328 if len(test_name) < overflow_columns + len(ellipsis) + 2: 329 # We don't have enough space even if we elide, just show the test filename. 330 fs = self._port.host.filesystem 331 test_name = fs.split(test_name)[1] 332 else: 333 new_length = len(test_name) - overflow_columns - len(ellipsis) 334 prefix = int(new_length / 2) 335 test_name = test_name[:prefix] + ellipsis + test_name[-(new_length - prefix):] 336 return format_string % (self.num_completed, self.num_tests, test_name, suffix) 337 338 def print_started_test(self, test_name): 339 self._running_tests.append(test_name) 340 if len(self._running_tests) > 1: 341 suffix = ' (+%d)' % (len(self._running_tests) - 1) 342 else: 343 suffix = '' 344 if self._options.verbose: 345 write = self._meter.write_update 346 else: 347 write = self._meter.write_throttled_update 348 write(self._test_status_line(test_name, suffix)) 349 350 def print_finished_test(self, result, expected, exp_str, got_str): 351 self.num_completed += 1 352 test_name = result.test_name 353 354 result_message = self._result_message(result.type, result.failures, expected, 355 self._options.timing, result.test_run_time) 356 357 if self._options.details: 358 self._print_test_trace(result, exp_str, got_str) 359 elif self._options.verbose or not expected: 360 self.writeln(self._test_status_line(test_name, result_message)) 361 elif self.num_completed == self.num_tests: 362 self._meter.write_update('') 363 else: 364 if test_name == self._running_tests[0]: 365 self._completed_tests.insert(0, [test_name, result_message]) 366 else: 367 self._completed_tests.append([test_name, result_message]) 368 369 for test_name, result_message in self._completed_tests: 370 self._meter.write_throttled_update(self._test_status_line(test_name, result_message)) 371 self._completed_tests = [] 372 self._running_tests.remove(test_name) 373 374 def _result_message(self, result_type, failures, expected, timing, test_run_time): 375 exp_string = ' unexpectedly' if not expected else '' 376 timing_string = ' %.4fs' % test_run_time if timing else '' 377 if result_type == test_expectations.PASS: 378 return ' passed%s%s' % (exp_string, timing_string) 379 else: 380 return ' failed%s (%s)%s' % (exp_string, ', '.join(failure.message() for failure in failures), timing_string) 381 382 def _print_test_trace(self, result, exp_str, got_str): 383 test_name = result.test_name 384 self._print_default(self._test_status_line(test_name, '')) 385 386 base = self._port.lookup_virtual_test_base(test_name) 387 if base: 388 args = ' '.join(self._port.lookup_virtual_test_args(test_name)) 389 self._print_default(' base: %s' % base) 390 self._print_default(' args: %s' % args) 391 392 references = self._port.reference_files(test_name) 393 if references: 394 for _, filename in references: 395 self._print_default(' ref: %s' % self._port.relative_test_filename(filename)) 396 else: 397 for extension in ('.txt', '.png', '.wav'): 398 self._print_baseline(test_name, extension) 399 400 self._print_default(' exp: %s' % exp_str) 401 self._print_default(' got: %s' % got_str) 402 self._print_default(' took: %-.3f' % result.test_run_time) 403 self._print_default('') 404 405 def _print_baseline(self, test_name, extension): 406 baseline = self._port.expected_filename(test_name, extension) 407 if self._port._filesystem.exists(baseline): 408 relpath = self._port.relative_test_filename(baseline) 409 else: 410 relpath = '<none>' 411 self._print_default(' %s: %s' % (extension[1:], relpath)) 412 413 def _print_quiet(self, msg): 414 self.writeln(msg) 415 416 def _print_default(self, msg): 417 if not self._options.quiet: 418 self.writeln(msg) 419 420 def _print_debug(self, msg): 421 if self._options.debug_rwt_logging: 422 self.writeln(msg) 423 424 def write_throttled_update(self, msg): 425 self._meter.write_throttled_update(msg) 426 427 def write_update(self, msg): 428 self._meter.write_update(msg) 429 430 def writeln(self, msg): 431 self._meter.writeln(msg) 432 433 def flush(self): 434 self._meter.flush() 435
