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

On my quad-core mac, this was <100 tests. I'm hoping we can gather
some data for implementing bug 9324.

Review URL: http://codereview.chromium.org/63127

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@13375 0039d316-1c4b-4281-b951-d872f2087c98

2 files changed, 36 insertions, 5 deletions

diff --git a/webkit/tools/layout_tests/layout_package/test_shell_thread.py b/webkit/tools/layout_tests/layout_package/test_shell_thread.py
index 61a5d87..bd1e142 100644
--- a/webkit/tools/layout_tests/layout_package/test_shell_thread.py
+++ b/webkit/tools/layout_tests/layout_package/test_shell_thread.py
@@ -175,6 +175,7 @@ class TestShellThread(threading.Thread):
     self._canceled = False
     self._exception_info = None
     self._timing_stats = {}
+    self._test_times = []
 
     # Current directory of tests we're running.
     self._current_dir = None
@@ -203,6 +204,11 @@ class TestShellThread(threading.Thread):
     (number of tests in that directory, time to run the tests)"""
     return self._timing_stats;
 
+  def GetIndividualTestTimingStats(self):
+    """Returns a list of (time, test_filename) tuples where time is the
+    time it took to run the test."""
+    return self._test_times
+
   def Cancel(self):
     """Set a flag telling this thread to quit."""
     self._canceled = True
@@ -339,10 +345,15 @@ class TestShellThread(threading.Thread):
     # try to recover here.
     self._test_shell_proc.stdin.flush()
 
+    start_time = time.time()
+
     # ...and read the response
-    return ProcessOutput(self._test_shell_proc, filename, test_uri,
-                         self._test_types, self._test_args,
-                         self._options.target)
+    failures = ProcessOutput(self._test_shell_proc, filename, test_uri,
+        self._test_types, self._test_args, self._options.target)
+
+    time_to_run_test = time.time() - start_time
+    self._test_times.append((time_to_run_test, filename))
+    return failures
 
 
   def _EnsureTestShellIsRunning(self):
diff --git a/webkit/tools/layout_tests/run_webkit_tests.py b/webkit/tools/layout_tests/run_webkit_tests.py
index 476a96c..8b0af0e 100755
--- a/webkit/tools/layout_tests/run_webkit_tests.py
+++ b/webkit/tools/layout_tests/run_webkit_tests.py
@@ -480,6 +480,7 @@ class TestRunner:
     # 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():
@@ -490,6 +491,7 @@ class TestRunner:
           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()
@@ -507,7 +509,8 @@ class TestRunner:
     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
 
@@ -535,7 +538,22 @@ class TestRunner:
     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 = \
+        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]
@@ -932,6 +950,8 @@ if '__main__' == __name__:
   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="",