WebKitTools/Scripts/webkitpy/layout_tests/layout_package/dump_render_tree_thread.py

   1 #!/usr/bin/env python
   2 # Copyright (C) 2010 Google Inc. All rights reserved.
   3 # Copyright (C) 2010 Gabor Rapcsanyi (rgabor@inf.u-szeged.hu), University of Szeged
   4 #
   5 # Redistribution and use in source and binary forms, with or without
   6 # modification, are permitted provided that the following conditions are
   7 # met:
   8 #
   9 #     * Redistributions of source code must retain the above copyright
  10 # notice, this list of conditions and the following disclaimer.
  11 #     * Redistributions in binary form must reproduce the above
  12 # copyright notice, this list of conditions and the following disclaimer
  13 # in the documentation and/or other materials provided with the
  14 # distribution.
  15 #     * Neither the name of Google Inc. nor the names of its
  16 # contributors may be used to endorse or promote products derived from
  17 # this software without specific prior written permission.
  18 #
  19 # THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
  20 # "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
  21 # LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
  22 # A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
  23 # OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
  24 # SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
  25 # LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
  26 # DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
  27 # THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
  28 # (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
  29 # OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
  30
  31 """A Thread object for running DumpRenderTree and processing URLs from a
  32 shared queue.
  33
  34 Each thread runs a separate instance of the DumpRenderTree binary and validates
  35 the output.  When there are no more URLs to process in the shared queue, the
  36 thread exits.
  37 """
  38
  39 from __future__ import with_statement
  40
  41 import codecs
  42 import copy
  43 import logging
  44 import os
  45 import Queue
  46 import signal
  47 import sys
  48 import thread
  49 import threading
  50 import time
  51 import traceback
  52
  53 import test_failures
  54 import test_results
  55
  56 _log = logging.getLogger("webkitpy.layout_tests.layout_package."
  57                          "dump_render_tree_thread")
  58
  59
  60 def find_thread_stack(id):
  61     """Returns a stack object that can be used to dump a stack trace for
  62     the given thread id (or None if the id is not found)."""
  63     for thread_id, stack in sys._current_frames().items():
  64         if thread_id == id:
  65             return stack
  66     return None
  67
  68
  69 def log_stack(stack):
  70     """Log a stack trace to log.error()."""
  71     for filename, lineno, name, line in traceback.extract_stack(stack):
  72         _log.error('File: "%s", line %d, in %s' % (filename, lineno, name))
  73         if line:
  74             _log.error('  %s' % line.strip())
  75
  76
  77 def _process_output(port, options, test_info, test_types, test_args,
  78                     crash, timeout, test_run_time, actual_checksum,
  79                     output, error):
  80     """Receives the output from a DumpRenderTree process, subjects it to a
  81     number of tests, and returns a list of failure types the test produced.
  82
  83     Args:
  84       port: port-specific hooks
  85       options: command line options argument from optparse
  86       proc: an active DumpRenderTree process
  87       test_info: Object containing the test filename, uri and timeout
  88       test_types: list of test types to subject the output to
  89       test_args: arguments to be passed to each test
  90
  91     Returns: a TestResult object
  92     """
  93     failures = []
  94
  95     # Some test args, such as the image hash, may be added or changed on a
  96     # test-by-test basis.
  97     local_test_args = copy.copy(test_args)
  98
  99     local_test_args.hash = actual_checksum
 100
 101     if crash:
 102         failures.append(test_failures.FailureCrash())
 103     if timeout:
 104         failures.append(test_failures.FailureTimeout())
 105
 106     if crash:
 107         _log.debug("Stacktrace for %s:\n%s" % (test_info.filename, error))
 108         # Strip off "file://" since RelativeTestFilename expects
 109         # filesystem paths.
 110         filename = os.path.join(options.results_directory,
 111                                 port.relative_test_filename(
 112                                 test_info.filename))
 113         filename = os.path.splitext(filename)[0] + "-stack.txt"
 114         port.maybe_make_directory(os.path.split(filename)[0])
 115         with codecs.open(filename, "wb", "utf-8") as file:
 116             file.write(error)
 117     elif error:
 118         _log.debug("Previous test output stderr lines:\n%s" % error)
 119
 120     # Check the output and save the results.
 121     start_time = time.time()
 122     time_for_diffs = {}
 123     for test_type in test_types:
 124         start_diff_time = time.time()
 125         new_failures = test_type.compare_output(port, test_info.filename,
 126                                                 output, local_test_args,
 127                                                 options.configuration)
 128         # Don't add any more failures if we already have a crash, so we don't
 129         # double-report those tests. We do double-report for timeouts since
 130         # we still want to see the text and image output.
 131         if not crash:
 132             failures.extend(new_failures)
 133         time_for_diffs[test_type.__class__.__name__] = (
 134             time.time() - start_diff_time)
 135
 136     total_time_for_all_diffs = time.time() - start_diff_time
 137     return test_results.TestResult(test_info.filename, failures, test_run_time,
 138                                    total_time_for_all_diffs, time_for_diffs)
 139
 140
 141 def _pad_timeout(timeout):
 142     """Returns a safe multiple of the per-test timeout value to use
 143     to detect hung test threads.
 144
 145     """
 146     # When we're running one test per DumpRenderTree process, we can
 147     # enforce a hard timeout.  The DumpRenderTree watchdog uses 2.5x
 148     # the timeout; we want to be larger than that.
 149     return timeout * 3
 150
 151
 152 def _milliseconds_to_seconds(msecs):
 153     return float(msecs) / 1000.0
 154
 155
 156 def _image_hash(test_info, test_args, options):
 157     """Returns the image hash of the test if it's needed, otherwise None."""
 158     if (test_args.new_baseline or test_args.reset_results or not options.pixel_tests):
 159         return None
 160     return test_info.image_hash()
 161
 162
 163 class SingleTestThread(threading.Thread):
 164     """Thread wrapper for running a single test file."""
 165
 166     def __init__(self, port, options, test_info, test_types, test_args):
 167         """
 168         Args:
 169           port: object implementing port-specific hooks
 170           options: command line argument object from optparse
 171           test_info: Object containing the test filename, uri and timeout
 172           test_types: A list of TestType objects to run the test output
 173               against.
 174           test_args: A TestArguments object to pass to each TestType.
 175         """
 176
 177         threading.Thread.__init__(self)
 178         self._port = port
 179         self._options = options
 180         self._test_info = test_info
 181         self._test_types = test_types
 182         self._test_args = test_args
 183         self._driver = None
 184
 185     def run(self):
 186         self._covered_run()
 187
 188     def _covered_run(self):
 189         # FIXME: this is a separate routine to work around a bug
 190         # in coverage: see http://bitbucket.org/ned/coveragepy/issue/85.
 191         test_info = self._test_info
 192         self._driver = self._port.create_driver(self._test_args.png_path,
 193                                                 self._options)
 194         self._driver.start()
 195         image_hash = _image_hash(test_info, self._test_args, self._options)
 196         start = time.time()
 197         crash, timeout, actual_checksum, output, error = \
 198             self._driver.run_test(test_info.uri.strip(), test_info.timeout,
 199                                   image_hash)
 200         end = time.time()
 201         self._test_result = _process_output(self._port, self._options,
 202             test_info, self._test_types, self._test_args,
 203             crash, timeout, end - start,
 204             actual_checksum, output, error)
 205         self._driver.stop()
 206
 207     def get_test_result(self):
 208         return self._test_result
 209
 210
 211 class WatchableThread(threading.Thread):
 212     """This class abstracts an interface used by
 213     run_webkit_tests.TestRunner._wait_for_threads_to_finish for thread
 214     management."""
 215     def __init__(self):
 216         threading.Thread.__init__(self)
 217         self._canceled = False
 218         self._exception_info = None
 219         self._next_timeout = None
 220         self._thread_id = None
 221
 222     def cancel(self):
 223         """Set a flag telling this thread to quit."""
 224         self._canceled = True
 225
 226     def clear_next_timeout(self):
 227         """Mark a flag telling this thread to stop setting timeouts."""
 228         self._timeout = 0
 229
 230     def exception_info(self):
 231         """If run() terminated on an uncaught exception, return it here
 232         ((type, value, traceback) tuple).
 233         Returns None if run() terminated normally. Meant to be called after
 234         joining this thread."""
 235         return self._exception_info
 236
 237     def id(self):
 238         """Return a thread identifier."""
 239         return self._thread_id
 240
 241     def next_timeout(self):
 242         """Return the time the test is supposed to finish by."""
 243         return self._next_timeout
 244
 245
 246 class TestShellThread(WatchableThread):
 247     def __init__(self, port, options, filename_list_queue, result_queue,
 248                  test_types, test_args):
 249         """Initialize all the local state for this DumpRenderTree thread.
 250
 251         Args:
 252           port: interface to port-specific hooks
 253           options: command line options argument from optparse
 254           filename_list_queue: A thread safe Queue class that contains lists
 255               of tuples of (filename, uri) pairs.
 256           result_queue: A thread safe Queue class that will contain
 257               serialized TestResult objects.
 258           test_types: A list of TestType objects to run the test output
 259               against.
 260           test_args: A TestArguments object to pass to each TestType.
 261
 262         """
 263         WatchableThread.__init__(self)
 264         self._port = port
 265         self._options = options
 266         self._filename_list_queue = filename_list_queue
 267         self._result_queue = result_queue
 268         self._filename_list = []
 269         self._test_types = test_types
 270         self._test_args = test_args
 271         self._driver = None
 272         self._test_group_timing_stats = {}
 273         self._test_results = []
 274         self._num_tests = 0
 275         self._start_time = 0
 276         self._stop_time = 0
 277         self._have_http_lock = False
 278         self._http_lock_wait_begin = 0
 279         self._http_lock_wait_end = 0
 280
 281         # Current group of tests we're running.
 282         self._current_group = None
 283         # Number of tests in self._current_group.
 284         self._num_tests_in_current_group = None
 285         # Time at which we started running tests from self._current_group.
 286         self._current_group_start_time = None
 287
 288     def get_test_group_timing_stats(self):
 289         """Returns a dictionary mapping test group to a tuple of
 290         (number of tests in that group, time to run the tests)"""
 291         return self._test_group_timing_stats
 292
 293     def get_test_results(self):
 294         """Return the list of all tests run on this thread.
 295
 296         This is used to calculate per-thread statistics.
 297
 298         """
 299         return self._test_results
 300
 301     def get_total_time(self):
 302         return max(self._stop_time - self._start_time -
 303                    self._http_lock_wait_time(), 0.0)
 304
 305     def get_num_tests(self):
 306         return self._num_tests
 307
 308     def run(self):
 309         """Delegate main work to a helper method and watch for uncaught
 310         exceptions."""
 311         self._covered_run()
 312
 313     def _covered_run(self):
 314         # FIXME: this is a separate routine to work around a bug
 315         # in coverage: see http://bitbucket.org/ned/coveragepy/issue/85.
 316         self._thread_id = thread.get_ident()
 317         self._start_time = time.time()
 318         self._num_tests = 0
 319         try:
 320             _log.debug('%s starting' % (self.getName()))
 321             self._run(test_runner=None, result_summary=None)
 322             _log.debug('%s done (%d tests)' % (self.getName(),
 323                        self.get_num_tests()))
 324         except KeyboardInterrupt:
 325             self._exception_info = sys.exc_info()
 326             _log.debug("%s interrupted" % self.getName())
 327         except:
 328             # Save the exception for our caller to see.
 329             self._exception_info = sys.exc_info()
 330             self._stop_time = time.time()
 331             _log.error('%s dying, exception raised' % self.getName())
 332
 333         self._stop_time = time.time()
 334
 335     def run_in_main_thread(self, test_runner, result_summary):
 336         """This hook allows us to run the tests from the main thread if
 337         --num-test-shells==1, instead of having to always run two or more
 338         threads. This allows us to debug the test harness without having to
 339         do multi-threaded debugging."""
 340         self._run(test_runner, result_summary)
 341
 342     def cancel(self):
 343         """Clean up http lock and set a flag telling this thread to quit."""
 344         self._stop_servers_with_lock()
 345         WatchableThread.cancel(self)
 346
 347     def next_timeout(self):
 348         """Return the time the test is supposed to finish by."""
 349         if self._next_timeout:
 350             return self._next_timeout + self._http_lock_wait_time()
 351         return self._next_timeout
 352
 353     def _http_lock_wait_time(self):
 354         """Return the time what http locking takes."""
 355         if self._http_lock_wait_begin == 0:
 356             return 0
 357         if self._http_lock_wait_end == 0:
 358             return time.time() - self._http_lock_wait_begin
 359         return self._http_lock_wait_end - self._http_lock_wait_begin
 360
 361     def _run(self, test_runner, result_summary):
 362         """Main work entry point of the thread. Basically we pull urls from the
 363         filename queue and run the tests until we run out of urls.
 364
 365         If test_runner is not None, then we call test_runner.UpdateSummary()
 366         with the results of each test."""
 367         batch_size = self._options.batch_size
 368         batch_count = 0
 369
 370         # Append tests we're running to the existing tests_run.txt file.
 371         # This is created in run_webkit_tests.py:_PrepareListsAndPrintOutput.
 372         tests_run_filename = os.path.join(self._options.results_directory,
 373                                           "tests_run.txt")
 374         tests_run_file = codecs.open(tests_run_filename, "a", "utf-8")
 375
 376         while True:
 377             if self._canceled:
 378                 _log.debug('Testing cancelled')
 379                 tests_run_file.close()
 380                 return
 381
 382             if len(self._filename_list) is 0:
 383                 if self._current_group is not None:
 384                     self._test_group_timing_stats[self._current_group] = \
 385                         (self._num_tests_in_current_group,
 386                          time.time() - self._current_group_start_time)
 387
 388                 try:
 389                     self._current_group, self._filename_list = \
 390                         self._filename_list_queue.get_nowait()
 391                 except Queue.Empty:
 392                     self._stop_servers_with_lock()
 393                     self._kill_dump_render_tree()
 394                     tests_run_file.close()
 395                     return
 396
 397                 if self._current_group == "tests_to_http_lock":
 398                     self._start_servers_with_lock()
 399                 elif self._have_http_lock:
 400                     self._stop_servers_with_lock()
 401
 402                 self._num_tests_in_current_group = len(self._filename_list)
 403                 self._current_group_start_time = time.time()
 404
 405             test_info = self._filename_list.pop()
 406
 407             # We have a url, run tests.
 408             batch_count += 1
 409             self._num_tests += 1
 410             if self._options.run_singly:
 411                 result = self._run_test_singly(test_info)
 412             else:
 413                 result = self._run_test(test_info)
 414
 415             filename = test_info.filename
 416             tests_run_file.write(filename + "\n")
 417             if result.failures:
 418                 # Check and kill DumpRenderTree if we need to.
 419                 if len([1 for f in result.failures
 420                         if f.should_kill_dump_render_tree()]):
 421                     self._kill_dump_render_tree()
 422                     # Reset the batch count since the shell just bounced.
 423                     batch_count = 0
 424                 # Print the error message(s).
 425                 error_str = '\n'.join(['  ' + f.message() for
 426                                        f in result.failures])
 427                 _log.debug("%s %s failed:\n%s" % (self.getName(),
 428                            self._port.relative_test_filename(filename),
 429                            error_str))
 430             else:
 431                 _log.debug("%s %s passed" % (self.getName(),
 432                            self._port.relative_test_filename(filename)))
 433             self._result_queue.put(result.dumps())
 434
 435             if batch_size > 0 and batch_count >= batch_size:
 436                 # Bounce the shell and reset count.
 437                 self._kill_dump_render_tree()
 438                 batch_count = 0
 439
 440             if test_runner:
 441                 test_runner.update_summary(result_summary)
 442
 443     def _run_test_singly(self, test_info):
 444         """Run a test in a separate thread, enforcing a hard time limit.
 445
 446         Since we can only detect the termination of a thread, not any internal
 447         state or progress, we can only run per-test timeouts when running test
 448         files singly.
 449
 450         Args:
 451           test_info: Object containing the test filename, uri and timeout
 452
 453         Returns:
 454           A TestResult
 455
 456         """
 457         worker = SingleTestThread(self._port,
 458                                   self._options,
 459                                   test_info,
 460                                   self._test_types,
 461                                   self._test_args)
 462
 463         worker.start()
 464
 465         thread_timeout = _milliseconds_to_seconds(
 466             _pad_timeout(int(test_info.timeout)))
 467         thread._next_timeout = time.time() + thread_timeout
 468         worker.join(thread_timeout)
 469         if worker.isAlive():
 470             # If join() returned with the thread still running, the
 471             # DumpRenderTree is completely hung and there's nothing
 472             # more we can do with it.  We have to kill all the
 473             # DumpRenderTrees to free it up. If we're running more than
 474             # one DumpRenderTree thread, we'll end up killing the other
 475             # DumpRenderTrees too, introducing spurious crashes. We accept
 476             # that tradeoff in order to avoid losing the rest of this
 477             # thread's results.
 478             _log.error('Test thread hung: killing all DumpRenderTrees')
 479             if worker._driver:
 480                 worker._driver.stop()
 481
 482         try:
 483             result = worker.get_test_result()
 484         except AttributeError, e:
 485             # This gets raised if the worker thread has already exited.
 486             failures = []
 487             _log.error('Cannot get results of test: %s' %
 488                        test_info.filename)
 489             result = test_results.TestResult(test_info.filename, failures=[],
 490                 test_run_time=0, total_time_for_all_diffs=0, time_for_diffs=0)
 491
 492         return result
 493
 494     def _run_test(self, test_info):
 495         """Run a single test file using a shared DumpRenderTree process.
 496
 497         Args:
 498           test_info: Object containing the test filename, uri and timeout
 499
 500         Returns: a TestResult object.
 501         """
 502         self._ensure_dump_render_tree_is_running()
 503         # The pixel_hash is used to avoid doing an image dump if the
 504         # checksums match, so it should be set to a blank value if we
 505         # are generating a new baseline.  (Otherwise, an image from a
 506         # previous run will be copied into the baseline.)
 507         image_hash = _image_hash(test_info, self._test_args, self._options)
 508         start = time.time()
 509
 510         thread_timeout = _milliseconds_to_seconds(
 511              _pad_timeout(int(test_info.timeout)))
 512         self._next_timeout = start + thread_timeout
 513
 514         crash, timeout, actual_checksum, output, error = \
 515            self._driver.run_test(test_info.uri, test_info.timeout, image_hash)
 516         end = time.time()
 517
 518         result = _process_output(self._port, self._options,
 519                                  test_info, self._test_types,
 520                                  self._test_args, crash,
 521                                  timeout, end - start, actual_checksum,
 522                                  output, error)
 523         self._test_results.append(result)
 524         return result
 525
 526     def _ensure_dump_render_tree_is_running(self):
 527         """Start the shared DumpRenderTree, if it's not running.
 528
 529         This is not for use when running tests singly, since those each start
 530         a separate DumpRenderTree in their own thread.
 531
 532         """
 533         # poll() is not threadsafe and can throw OSError due to:
 534         # http://bugs.python.org/issue1731717
 535         if (not self._driver or self._driver.poll() is not None):
 536             self._driver = self._port.create_driver(self._test_args.png_path,
 537                                                     self._options)
 538             self._driver.start()
 539
 540     def _start_servers_with_lock(self):
 541         """Acquire http lock and start the servers."""
 542         self._http_lock_wait_begin = time.time()
 543         _log.debug('Acquire http lock ...')
 544         self._port.acquire_http_lock()
 545         _log.debug('Starting HTTP server ...')
 546         self._port.start_http_server()
 547         _log.debug('Starting WebSocket server ...')
 548         self._port.start_websocket_server()
 549         self._http_lock_wait_end = time.time()
 550         self._have_http_lock = True
 551
 552     def _stop_servers_with_lock(self):
 553         """Stop the servers and release http lock."""
 554         if self._have_http_lock:
 555             _log.debug('Stopping HTTP server ...')
 556             self._port.stop_http_server()
 557             _log.debug('Stopping WebSocket server ...')
 558             self._port.stop_websocket_server()
 559             _log.debug('Release http lock ...')
 560             self._port.release_http_lock()
 561             self._have_http_lock = False
 562
 563     def _kill_dump_render_tree(self):
 564         """Kill the DumpRenderTree process if it's running."""
 565         if self._driver:
 566             self._driver.stop()
 567             self._driver = None