2e9ac9474207ec706e8a0b0a968c2731b50d3d20
[WebKit-https.git] / Tools / Scripts / webkitpy / layout_tests / views / printing.py
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('-q', '--quiet', action='store_true', default=False,
46                              help='run quietly (errors, warnings, and progress only)'),
47         optparse.make_option('-v', '--verbose', action='store_true', default=False,
48                              help='print a summarized result for every test (one line per test)'),
49         optparse.make_option('--details', action='store_true', default=False,
50                              help='print detailed results for every test'),
51         optparse.make_option('--debug-rwt-logging', action='store_true', default=False,
52                              help='print timestamps and debug information for run-webkit-tests itself'),
53     ]
54
55
56 class Printer(object):
57     """Class handling all non-debug-logging printing done by run-webkit-tests."""
58
59     def __init__(self, port, options, regular_output, logger=None):
60         self.num_started = 0
61         self.num_tests = 0
62         self._port = port
63         self._options = options
64         self._meter = MeteredStream(regular_output, options.debug_rwt_logging, logger=logger,
65                                     number_of_columns=self._port.host.platform.terminal_width())
66         self._running_tests = []
67         self._completed_tests = []
68
69     def cleanup(self):
70         self._meter.cleanup()
71
72     def __del__(self):
73         self.cleanup()
74
75     def print_config(self, results_directory):
76         self._print_default("Using port '%s'" % self._port.name())
77         self._print_default("Test configuration: %s" % self._port.test_configuration())
78         self._print_default("Placing test results in %s" % results_directory)
79
80         # FIXME: should these options be in printing_options?
81         if self._options.new_baseline:
82             self._print_default("Placing new baselines in %s" % self._port.baseline_path())
83
84         fs = self._port.host.filesystem
85         fallback_path = [fs.split(x)[1] for x in self._port.baseline_search_path()]
86         self._print_default("Baseline search path: %s -> generic" % " -> ".join(fallback_path))
87
88         self._print_default("Using %s build" % self._options.configuration)
89         if self._options.pixel_tests:
90             self._print_default("Pixel tests enabled")
91         else:
92             self._print_default("Pixel tests disabled")
93
94         self._print_default("Regular timeout: %s, slow test timeout: %s" %
95                   (self._options.time_out_ms, self._options.slow_time_out_ms))
96
97         self._print_default('Command line: ' + ' '.join(self._port.driver_cmd_line()))
98         self._print_default('')
99
100     def print_found(self, num_all_test_files, num_to_run, repeat_each, iterations):
101         found_str = 'Found %s; running %d' % (grammar.pluralize(num_all_test_files, "test"), num_to_run)
102         if repeat_each * iterations > 1:
103             found_str += ' (%s each: --repeat-each=%d --iterations=%d)' % (grammar.pluralize(repeat_each * iterations, "time"), repeat_each, iterations)
104         found_str += ', skipping %d' % (num_all_test_files - num_to_run)
105         self._print_default(found_str + '.')
106
107     def print_expected(self, run_results, tests_with_result_type_callback):
108         self._print_expected_results_of_type(run_results, test_expectations.PASS, "passes", tests_with_result_type_callback)
109         self._print_expected_results_of_type(run_results, test_expectations.FAIL, "failures", tests_with_result_type_callback)
110         self._print_expected_results_of_type(run_results, test_expectations.FLAKY, "flaky", tests_with_result_type_callback)
111         self._print_debug('')
112
113     def print_workers_and_shards(self, num_workers, num_shards):
114         driver_name = self._port.driver_name()
115         if num_workers == 1:
116             self._print_default("Running 1 %s." % driver_name)
117             self._print_debug("(%s)." % grammar.pluralize(num_shards, "shard"))
118         else:
119             self._print_default("Running %s in parallel." % (grammar.pluralize(num_workers, driver_name)))
120             self._print_debug("(%d shards)." % num_shards)
121         self._print_default('')
122
123     def _print_expected_results_of_type(self, run_results, result_type, result_type_str, tests_with_result_type_callback):
124         tests = tests_with_result_type_callback(result_type)
125         now = run_results.tests_by_timeline[test_expectations.NOW]
126         wontfix = run_results.tests_by_timeline[test_expectations.WONTFIX]
127
128         # We use a fancy format string in order to print the data out in a
129         # nicely-aligned table.
130         fmtstr = ("Expect: %%5d %%-8s (%%%dd now, %%%dd wontfix)"
131                   % (self._num_digits(now), self._num_digits(wontfix)))
132         self._print_debug(fmtstr % (len(tests), result_type_str, len(tests & now), len(tests & wontfix)))
133
134     def _num_digits(self, num):
135         ndigits = 1
136         if len(num):
137             ndigits = int(math.log10(len(num))) + 1
138         return ndigits
139
140     def print_results(self, run_time, run_results, summarized_results):
141         self._print_timing_statistics(run_time, run_results)
142         self._print_one_line_summary(run_results.total - run_results.expected_skips,
143                                      run_results.expected - run_results.expected_skips,
144                                      run_results.unexpected)
145
146     def _print_timing_statistics(self, total_time, run_results):
147         self._print_debug("Test timing:")
148         self._print_debug("  %6.2f total testing time" % total_time)
149         self._print_debug("")
150
151         self._print_worker_statistics(run_results, int(self._options.child_processes))
152         self._print_aggregate_test_statistics(run_results)
153         self._print_individual_test_times(run_results)
154         self._print_directory_timings(run_results)
155
156     def _print_worker_statistics(self, run_results, num_workers):
157         self._print_debug("Thread timing:")
158         stats = {}
159         cuml_time = 0
160         for result in run_results.results_by_name.values():
161             stats.setdefault(result.worker_name, {'num_tests': 0, 'total_time': 0})
162             stats[result.worker_name]['num_tests'] += 1
163             stats[result.worker_name]['total_time'] += result.total_run_time
164             cuml_time += result.total_run_time
165
166         for worker_name in stats:
167             self._print_debug("    %10s: %5d tests, %6.2f secs" % (worker_name, stats[worker_name]['num_tests'], stats[worker_name]['total_time']))
168         self._print_debug("   %6.2f cumulative, %6.2f optimal" % (cuml_time, cuml_time / num_workers))
169         self._print_debug("")
170
171     def _print_aggregate_test_statistics(self, run_results):
172         times_for_dump_render_tree = [result.test_run_time for result in run_results.results_by_name.values()]
173         self._print_statistics_for_test_timings("PER TEST TIME IN TESTSHELL (seconds):", times_for_dump_render_tree)
174
175     def _print_individual_test_times(self, run_results):
176         # Reverse-sort by the time spent in DumpRenderTree.
177
178         individual_test_timings = sorted(run_results.results_by_name.values(), key=lambda result: result.test_run_time, reverse=True)
179         num_printed = 0
180         slow_tests = []
181         timeout_or_crash_tests = []
182         unexpected_slow_tests = []
183         for test_tuple in individual_test_timings:
184             test_name = test_tuple.test_name
185             is_timeout_crash_or_slow = False
186             if test_name in run_results.slow_tests:
187                 is_timeout_crash_or_slow = True
188                 slow_tests.append(test_tuple)
189
190             if test_name in run_results.failures_by_name:
191                 result = run_results.results_by_name[test_name].type
192                 if (result == test_expectations.TIMEOUT or
193                     result == test_expectations.CRASH):
194                     is_timeout_crash_or_slow = True
195                     timeout_or_crash_tests.append(test_tuple)
196
197             if (not is_timeout_crash_or_slow and num_printed < NUM_SLOW_TESTS_TO_LOG):
198                 num_printed = num_printed + 1
199                 unexpected_slow_tests.append(test_tuple)
200
201         self._print_debug("")
202         self._print_test_list_timing("%s slowest tests that are not marked as SLOW and did not timeout/crash:" %
203             NUM_SLOW_TESTS_TO_LOG, unexpected_slow_tests)
204         self._print_debug("")
205         self._print_test_list_timing("Tests marked as SLOW:", slow_tests)
206         self._print_debug("")
207         self._print_test_list_timing("Tests that timed out or crashed:", timeout_or_crash_tests)
208         self._print_debug("")
209
210     def _print_test_list_timing(self, title, test_list):
211         self._print_debug(title)
212         for test_tuple in test_list:
213             test_run_time = round(test_tuple.test_run_time, 1)
214             self._print_debug("  %s took %s seconds" % (test_tuple.test_name, test_run_time))
215
216     def _print_directory_timings(self, run_results):
217         stats = {}
218         for result in run_results.results_by_name.values():
219             stats.setdefault(result.shard_name, {'num_tests': 0, 'total_time': 0})
220             stats[result.shard_name]['num_tests'] += 1
221             stats[result.shard_name]['total_time'] += result.total_run_time
222
223         timings = []
224         for directory in stats:
225             timings.append((directory, round(stats[directory]['total_time'], 1), stats[directory]['num_tests']))
226         timings.sort()
227
228         self._print_debug("Time to process slowest subdirectories:")
229         min_seconds_to_print = 10
230         for timing in timings:
231             if timing[0] > min_seconds_to_print:
232                 self._print_debug("  %s took %s seconds to run %s tests." % timing)
233         self._print_debug("")
234
235     def _print_statistics_for_test_timings(self, title, timings):
236         self._print_debug(title)
237         timings.sort()
238
239         num_tests = len(timings)
240         if not num_tests:
241             return
242         percentile90 = timings[int(.9 * num_tests)]
243         percentile99 = timings[int(.99 * num_tests)]
244
245         if num_tests % 2 == 1:
246             median = timings[((num_tests - 1) / 2) - 1]
247         else:
248             lower = timings[num_tests / 2 - 1]
249             upper = timings[num_tests / 2]
250             median = (float(lower + upper)) / 2
251
252         mean = sum(timings) / num_tests
253
254         for timing in timings:
255             sum_of_deviations = math.pow(timing - mean, 2)
256
257         std_deviation = math.sqrt(sum_of_deviations / num_tests)
258         self._print_debug("  Median:          %6.3f" % median)
259         self._print_debug("  Mean:            %6.3f" % mean)
260         self._print_debug("  90th percentile: %6.3f" % percentile90)
261         self._print_debug("  99th percentile: %6.3f" % percentile99)
262         self._print_debug("  Standard dev:    %6.3f" % std_deviation)
263         self._print_debug("")
264
265     def _print_one_line_summary(self, total, expected, unexpected):
266         incomplete = total - expected - unexpected
267         incomplete_str = ''
268         if incomplete:
269             self._print_default("")
270             incomplete_str = " (%d didn't run)" % incomplete
271
272         if self._options.verbose or self._options.debug_rwt_logging or unexpected:
273             self.writeln("")
274
275         summary = ''
276         if unexpected == 0:
277             if expected == total:
278                 if expected > 1:
279                     summary = "All %d tests ran as expected." % expected
280                 else:
281                     summary = "The test ran as expected."
282             else:
283                 summary = "%s ran as expected%s." % (grammar.pluralize(expected, "test"), incomplete_str)
284         else:
285             summary = "%s ran as expected, %d didn't%s:" % (grammar.pluralize(expected, "test"), unexpected, incomplete_str)
286
287         self._print_quiet(summary)
288         self._print_quiet("")
289
290     def _test_status_line(self, test_name, suffix):
291         format_string = '[%d/%d] %s%s'
292         status_line = format_string % (self.num_started, self.num_tests, test_name, suffix)
293         if len(status_line) > self._meter.number_of_columns():
294             overflow_columns = len(status_line) - self._meter.number_of_columns()
295             ellipsis = '...'
296             if len(test_name) < overflow_columns + len(ellipsis) + 2:
297                 # We don't have enough space even if we elide, just show the test filename.
298                 fs = self._port.host.filesystem
299                 test_name = fs.split(test_name)[1]
300             else:
301                 new_length = len(test_name) - overflow_columns - len(ellipsis)
302                 prefix = int(new_length / 2)
303                 test_name = test_name[:prefix] + ellipsis + test_name[-(new_length - prefix):]
304         return format_string % (self.num_started, self.num_tests, test_name, suffix)
305
306     def print_started_test(self, test_name):
307         self.num_started += 1
308         self._running_tests.append(test_name)
309         if len(self._running_tests) > 1:
310             suffix = ' (+%d)' % (len(self._running_tests) - 1)
311         else:
312             suffix = ''
313         if self._options.verbose:
314             write = self._meter.write_update
315         else:
316             write = self._meter.write_throttled_update
317         write(self._test_status_line(test_name, suffix))
318
319     def print_finished_test(self, result, expected, exp_str, got_str):
320         test_name = result.test_name
321
322         result_message = self._result_message(result.type, result.failures, expected, self._options.verbose)
323
324         if self._options.details:
325             self._print_test_trace(result, exp_str, got_str)
326         elif (self._options.verbose and not self._options.debug_rwt_logging) or not expected:
327             self.writeln(self._test_status_line(test_name, result_message))
328         elif self.num_started == self.num_tests:
329             self._meter.write_update('')
330         else:
331             if test_name == self._running_tests[0]:
332                 self._completed_tests.insert(0, [test_name, result_message])
333             else:
334                 self._completed_tests.append([test_name, result_message])
335
336             for test_name, result_message in self._completed_tests:
337                 self._meter.write_throttled_update(self._test_status_line(test_name, result_message))
338             self._completed_tests = []
339         self._running_tests.remove(test_name)
340
341     def _result_message(self, result_type, failures, expected, verbose):
342         exp_string = ' unexpectedly' if not expected else ''
343         if result_type == test_expectations.PASS:
344             return ' passed%s' % exp_string
345         else:
346             return ' failed%s (%s)' % (exp_string, ', '.join(failure.message() for failure in failures))
347
348
349     def _print_test_trace(self, result, exp_str, got_str):
350         test_name = result.test_name
351         self._print_default(self._test_status_line(test_name, ''))
352
353         base = self._port.lookup_virtual_test_base(test_name)
354         if base:
355             args = ' '.join(self._port.lookup_virtual_test_args(test_name))
356             self._print_default(' base: %s' % base)
357             self._print_default(' args: %s' % args)
358
359         for extension in ('.txt', '.png', '.wav', '.webarchive'):
360             self._print_baseline(test_name, extension)
361
362         self._print_default('  exp: %s' % exp_str)
363         self._print_default('  got: %s' % got_str)
364         self._print_default(' took: %-.3f' % result.test_run_time)
365         self._print_default('')
366
367     def _print_baseline(self, test_name, extension):
368         baseline = self._port.expected_filename(test_name, extension)
369         if self._port._filesystem.exists(baseline):
370             relpath = self._port.relative_test_filename(baseline)
371         else:
372             relpath = '<none>'
373         self._print_default('  %s: %s' % (extension[1:], relpath))
374
375     def _print_quiet(self, msg):
376         self.writeln(msg)
377
378     def _print_default(self, msg):
379         if not self._options.quiet:
380             self.writeln(msg)
381
382     def _print_debug(self, msg):
383         if self._options.debug_rwt_logging:
384             self.writeln(msg)
385
386     def write_update(self, msg):
387         self._meter.write_update(msg)
388
389     def writeln(self, msg):
390         self._meter.writeln(msg)
391
392     def flush(self):
393         self._meter.flush()