Print times for individual tests that take longer than 1 second to run.

webkit/tools/layout_tests/run_webkit_tests.py

 #!/bin/env python
 # Copyright (c) 2006-2008 The Chromium Authors. All rights reserved.
 # Use of this source code is governed by a BSD-style license that can be
 # found in the LICENSE file.
 
 """Run layout tests using the test_shell.
 
 This is a port of the existing webkit test script run-webkit-tests.
 
 The TestRunner class runs a series of tests (TestType interface) against a set
@@ skipping 462 matching lines @@
     logging.info("Starting tests")
 
     # Create the output directory if it doesn't already exist.
     google.path_utils.MaybeMakeDirectory(self._options.results_directory)
 
     threads = self._InstantiateTestShellThreads(test_shell_binary)
 
     # Wait for the threads to finish and collect test failures.
     test_failures = {}
     test_timings = {}
+    individual_test_timings = []
     try:
       for thread in threads:
         while thread.isAlive():
           # Let it timeout occasionally so it can notice a KeyboardInterrupt
           # Actually, the timeout doesn't really matter: apparently it
           # suffices to not use an indefinite blocking join for it to
           # be interruptible by KeyboardInterrupt.
           thread.join(1.0)
         test_failures.update(thread.GetFailures())
         test_timings.update(thread.GetTimingStats())
+        individual_test_timings.extend(thread.GetIndividualTestTimingStats())
     except KeyboardInterrupt:
       for thread in threads:
         thread.Cancel()
       raise
     for thread in threads:
       # Check whether a TestShellThread died before normal completion.
       exception_info = thread.GetExceptionInfo()
       if exception_info is not None:
         # Re-raise the thread's exception here to make it clear that
         # testing was aborted. Otherwise, the tests that did not run
         # would be assumed to have passed.
         raise exception_info[0], exception_info[1], exception_info[2]
 
     print
     end_time = time.time()
     logging.info("%f total testing time" % (end_time - start_time))
 
-    self._PrintTimingsForRuns(test_timings)
+    print
+    self._PrintTimingStatistics(test_timings, individual_test_timings)
 
     print "-" * 78
 
     # Tests are done running. Compare failures with expected failures.
     regressions = self._CompareFailures(test_failures)
 
     print "-" * 78
 
     # Write summaries to stdout.
     self._PrintResults(test_failures, sys.stdout)
 
     # Write the same data to a log file.
     out_filename = os.path.join(self._options.results_directory, "score.txt")
     output_file = open(out_filename, "w")
     self._PrintResults(test_failures, output_file)
     output_file.close()
 
     # Write the summary to disk (results.html) and maybe open the test_shell
     # to this file.
     wrote_results = self._WriteResultsHtmlFile(test_failures, regressions)
     if not self._options.noshow_results and wrote_results:
       self._ShowResultsHtmlFile()
 
     sys.stdout.flush()
     sys.stderr.flush()
     return len(regressions)
 
-  def _PrintTimingsForRuns(self, test_timings):
+  def _PrintTimingStatistics(self, test_timings, individual_test_timings):
+    # Don't need to do any processing here for non-debug logging.
+    if logging.getLogger().getEffectiveLevel() > 10:
+      return
+
+    logging.debug("%s slowest tests:" % self._options.num_slow_tests_to_log)
+
+    individual_test_timings.sort(reverse=True)
+    slowests_tests = \

[tony, 2009/04/08 19:33:19]

Nit: Normally in python code we use () to get implicit line continuation.  E.g.,
slowest_tests = (
     blah blah   )

+        individual_test_timings[:self._options.num_slow_tests_to_log]
+
+    for test in slowests_tests:
+      logging.debug("%s took %s seconds" % (test[1], round(test[0], 1)))
+
+    print
+
     timings = []
     for directory in test_timings:
       num_tests, time = test_timings[directory]
       timings.append((round(time, 1), directory, num_tests))
     timings.sort()
 
     logging.debug("Time to process each each subdirectory:")
     for timing in timings:
       logging.debug("%s took %s seconds to run %s tests." % \
                     (timing[1], timing[0], timing[2]))
@@ skipping 376 matching lines @@
                            help="Number of testshells to run in parallel.")
   option_parser.add_option("", "--time-out-ms",
                            default=None,
                            help="Set the timeout for each test")
   option_parser.add_option("", "--run-singly", action="store_true",
                            default=False,
                            help="run a separate test_shell for each test")
   option_parser.add_option("", "--debug", action="store_true", default=False,
                            help="use the debug binary instead of the release "
                                 "binary")
+  option_parser.add_option("", "--num-slow-tests-to-log", default=50,
+                           help="Number of slow tests whose timings to print.")
   option_parser.add_option("", "--platform",
                            help="Override the platform for expected results")
   option_parser.add_option("", "--target", default="",
                            help="Set the build target configuration (overrides"
                                  " --debug)")
   # TODO(pamg): Support multiple levels of verbosity, and remove --sources.
   option_parser.add_option("-v", "--verbose", action="store_true",
                            default=False, help="include debug-level logging")
   option_parser.add_option("", "--sources", action="store_true",
                            help="show expected result file path for each test "
@@ skipping 26 matching lines @@
   option_parser.add_option("", "--run-part",
                            default=None,
                            help=("Run a specified part (n:m), the nth of m"
                                  " parts, of the layout tests"))
   option_parser.add_option("", "--batch-size",
                            default=None,
                            help=("Run a the tests in batches (n), after every "
                                  "n tests, the test shell is relaunched."))
   options, args = option_parser.parse_args()
   main(options, args)