Print median, mean and std_deviation for test running times.

Prints these for the time spent in test_shell and the time
spent doing each diff comparison.

Also removes the check to compute statistics only in debug mode.
That was an overoptimization (computing the statistics takes ~100ms).

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

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

2 files changed, 106 insertions, 45 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 bd1e142..c3ef1db 100644
--- a/webkit/tools/layout_tests/layout_package/test_shell_thread.py
+++ b/webkit/tools/layout_tests/layout_package/test_shell_thread.py
@@ -36,7 +36,7 @@ def ProcessOutput(proc, filename, test_uri, test_types, test_args, target):
     test_args: arguments to be passed to each test
     target: Debug or Release
 
-  Returns: a list of failure objects for the test being processed
+  Returns: a list of failure objects and times for the test being processed
   """
   outlines = []
   failures = []
@@ -46,6 +46,8 @@ def ProcessOutput(proc, filename, test_uri, test_types, test_args, target):
   # test-by-test basis.
   local_test_args = copy.copy(test_args)
 
+  start_time = time.time()
+
   line = proc.stdout.readline()
   while line.rstrip() != "#EOF":
     # Make sure we haven't crashed.
@@ -82,8 +84,12 @@ def ProcessOutput(proc, filename, test_uri, test_types, test_args, target):
       outlines.append(line)
     line = proc.stdout.readline()
 
+  end_test_time = time.time()
+
   # Check the output and save the results.
+  time_for_diffs = {}
   for test_type in test_types:
+    start_diff_time = time.time()
     new_failures = test_type.CompareOutput(filename, proc,
                                            ''.join(outlines),
                                            local_test_args,
@@ -92,8 +98,13 @@ def ProcessOutput(proc, filename, test_uri, test_types, test_args, target):
     # we don't double-report those tests.
     if not crash_or_timeout:
       failures.extend(new_failures)
+    time_for_diffs[test_type.__class__.__name__] = (
+        time.time() - start_diff_time)
 
-  return failures
+  total_time_for_all_diffs = time.time() - end_test_time
+  test_run_time = end_test_time - start_time
+  return TestStats(filename, failures, test_run_time, total_time_for_all_diffs,
+      time_for_diffs)
 
 
 def StartTestShell(command, args):
@@ -110,6 +121,14 @@ def StartTestShell(command, args):
                           stdout=subprocess.PIPE,
                           stderr=subprocess.STDOUT)
 
+class TestStats:
+  def __init__(self, filename, failures, test_run_time,
+               total_time_for_all_diffs, time_for_diffs):
+    self.filename = filename
+    self.failures = failures
+    self.test_run_time = test_run_time
+    self.total_time_for_all_diffs = total_time_for_all_diffs
+    self.time_for_diffs = time_for_diffs
 
 class SingleTestThread(threading.Thread):
   """Thread wrapper for running a single test file."""
@@ -130,20 +149,14 @@ class SingleTestThread(threading.Thread):
     self._test_types = test_types
     self._test_args = test_args
     self._target = target
-    self._single_test_failures = []
 
   def run(self):
     proc = StartTestShell(self._command, self._shell_args + [self._test_uri])
-    self._single_test_failures = ProcessOutput(proc,
-                                               self._filename,
-                                               self._test_uri,
-                                               self._test_types,
-                                               self._test_args,
-                                               self._target)
-
-  def GetFailures(self):
-    return self._single_test_failures
+    self._test_stats = ProcessOutput(proc, self._filename, self._test_uri,
+        self._test_types, self._test_args, self._target)
 
+  def GetTestStats(self):
+    return self._test_stats
 
 class TestShellThread(threading.Thread):
 
@@ -174,8 +187,8 @@ class TestShellThread(threading.Thread):
     self._failures = {}
     self._canceled = False
     self._exception_info = None
-    self._timing_stats = {}
-    self._test_times = []
+    self._directory_timing_stats = {}
+    self._test_stats = []
 
     # Current directory of tests we're running.
     self._current_dir = None
@@ -199,15 +212,15 @@ class TestShellThread(threading.Thread):
     TestFailures."""
     return self._failures
 
-  def GetTimingStats(self):
+  def GetDirectoryTimingStats(self):
     """Returns a dictionary mapping test directory to a tuple of
     (number of tests in that directory, time to run the tests)"""
-    return self._timing_stats;
+    return self._directory_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 GetIndividualTestStats(self):
+    """Returns a list of (test_filename, time_to_run_test,
+    total_time_for_all_diffs, time_for_diffs) tuples."""
+    return self._test_stats
 
   def Cancel(self):
     """Set a flag telling this thread to quit."""
@@ -249,7 +262,7 @@ class TestShellThread(threading.Thread):
 
       if len(self._filename_list) is 0:
         if self._current_dir is not None:
-          self._timing_stats[self._current_dir] = \
+          self._directory_timing_stats[self._current_dir] = \
               (self._num_tests_in_current_dir,
                time.time() - self._current_dir_start_time)
 
@@ -320,7 +333,15 @@ class TestShellThread(threading.Thread):
       platform_util = platform_utils.PlatformUtility('')
       platform_util.KillAllTestShells()
 
-    return worker.GetFailures()
+    try:
+      stats = worker.GetTestStats()
+      self._test_stats.append(stats)
+      failures = stats.failures
+    except AttributeError, e:
+      failures = []
+      logging.error('Cannot get results of test: %s' % filename)
+
+    return failures
 
 
   def _RunTest(self, filename, test_uri):
@@ -345,15 +366,11 @@ class TestShellThread(threading.Thread):
     # try to recover here.
     self._test_shell_proc.stdin.flush()
 
-    start_time = time.time()
-
-    # ...and read the response
-    failures = ProcessOutput(self._test_shell_proc, filename, test_uri,
+    stats = 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
+    self._test_stats.append(stats)
+    return stats.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 31296cd..5681f62 100755
--- a/webkit/tools/layout_tests/run_webkit_tests.py
+++ b/webkit/tools/layout_tests/run_webkit_tests.py
@@ -22,6 +22,7 @@ For details of the files' contents and purposes, see test_lists/README.
 
 import glob
 import logging
+import math
 import optparse
 import os
 import Queue
@@ -490,8 +491,8 @@ class TestRunner:
           # be interruptible by KeyboardInterrupt.
           thread.join(1.0)
         test_failures.update(thread.GetFailures())
-        test_timings.update(thread.GetTimingStats())
-        individual_test_timings.extend(thread.GetIndividualTestTimingStats())
+        test_timings.update(thread.GetDirectoryTimingStats())
+        individual_test_timings.extend(thread.GetIndividualTestStats())
     except KeyboardInterrupt:
       for thread in threads:
         thread.Cancel()
@@ -538,33 +539,76 @@ class TestRunner:
     sys.stderr.flush()
     return len(regressions)
 
-  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
+  def _PrintTimingStatistics(self, directory_test_timings,
+      individual_test_timings):
+    test_types = individual_test_timings[0].time_for_diffs.keys()
+    times_for_test_shell = []
+    times_for_diff_processing = []
+    times_per_test_type = {}
+    for test_type in test_types:
+      times_per_test_type[test_type] = []
+
+    for test_stats in individual_test_timings:
+      times_for_test_shell.append(test_stats.test_run_time)
+      times_for_diff_processing.append(test_stats.total_time_for_all_diffs)
+      time_for_diffs = test_stats.time_for_diffs
+      for test_type in test_types:
+        times_per_test_type[test_type].append(time_for_diffs[test_type])
+
+    logging.debug("PER TEST TIME IN TESTSHELL (seconds):")
+    self._PrintStatisticsForTestTimings(times_for_test_shell)
+    logging.debug("PER TEST DIFF PROCESSING TIMES (seconds):")
+    self._PrintStatisticsForTestTimings(times_for_diff_processing)
+    for test_type in test_types:
+      logging.debug("TEST TYPE: %s" % test_type)
+      self._PrintStatisticsForTestTimings(times_per_test_type[test_type])
+
+    # Reverse-sort by the time spent in test_shell.
+    individual_test_timings.sort(lambda a, b:
+        cmp(b.test_run_time, a.test_run_time))
+    slowests_tests = (
+        individual_test_timings[:self._options.num_slow_tests_to_log] )
 
     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)))
+      logging.debug("%s took %s seconds" % (test.filename,
+          round(test.test_run_time, 1)))
 
     print
 
     timings = []
-    for directory in test_timings:
-      num_tests, time = test_timings[directory]
-      timings.append((round(time, 1), directory, num_tests))
+    for directory in directory_test_timings:
+      num_tests, time_for_directory = directory_test_timings[directory]
+      timings.append((round(time_for_directory, 1), directory, num_tests))
     timings.sort()
 
-    logging.debug("Time to process each each subdirectory:")
+    logging.debug("Time to process each subdirectory:")
     for timing in timings:
       logging.debug("%s took %s seconds to run %s tests." % \
                     (timing[1], timing[0], timing[2]))
 
+  def _PrintStatisticsForTestTimings(self, timings):
+    """Prints the median, mean and standard deviation of the values in timings.
+    Args:
+      timings: A list of floats representing times.
+    """
+    num_tests = len(timings)
+    if num_tests % 2 == 1:
+      median = timings[((num_tests - 1) / 2) - 1]
+    else:
+      lower = timings[num_tests / 2 - 1]
+      upper = timings[num_tests / 2]
+      median = (float(lower + upper)) / 2
+
+    mean = sum(timings) / num_tests
+
+    for time in timings:
+      sum_of_deviations = math.pow(time - mean, 2)
+
+    std_deviation = math.sqrt(sum_of_deviations / num_tests)
+    logging.debug(("Median: %s, Mean %s, Standard deviation: %s\n" %
+        (median, mean, std_deviation)))
+
   def _PrintResults(self, test_failures, output):
     """Print a short summary to stdout about how many tests passed.