Adds code to run_tests.py which:

  * Prints the time taken to run each test
  * Prints the 5 slowest tests at the end of the test-run
  * Adds --hide-elapsed option to suppress elapsed time output

2 files changed, 80 insertions, 20 deletions

diff --git a/run_tests.py b/run_tests.py
index d5d8acd16..0944bb585 100644
--- a/run_tests.py
+++ b/run_tests.py
@@ -56,9 +56,11 @@ To run a single test module:
 """
 
 import gettext
+import heapq
 import os
 import unittest
 import sys
+import time
 
 gettext.install('nova', unicode=1)
 
@@ -183,9 +185,21 @@ class _NullColorizer(object):
         self.stream.write(text)
 
 
+def get_elapsed_time_color(elapsed_time):
+    if elapsed_time > 1.0:
+        return 'red'
+    elif elapsed_time > 0.25:
+        return 'yellow'
+    else:
+        return 'green'
+
+
 class NovaTestResult(result.TextTestResult):
     def __init__(self, *args, **kw):
+        self.show_elapsed = kw.pop('show_elapsed')
         result.TextTestResult.__init__(self, *args, **kw)
+        self.num_slow_tests = 5
+        self.slow_tests = []  # this is a fixed-sized heap
         self._last_case = None
         self.colorizer = None
         # NOTE(vish): reset stdout for the terminal check
@@ -200,25 +214,40 @@ class NovaTestResult(result.TextTestResult):
     def getDescription(self, test):
         return str(test)
 
-    # NOTE(vish): copied from unittest with edit to add color
-    def addSuccess(self, test):
-        unittest.TestResult.addSuccess(self, test)
+    def _handleElapsedTime(self, test):
+        self.elapsed_time = time.time() - self.start_time
+        item = (self.elapsed_time, test)
+        # Record only the n-slowest tests using heap
+        if len(self.slow_tests) >= self.num_slow_tests:
+            heapq.heappushpop(self.slow_tests, item)
+        else:
+            heapq.heappush(self.slow_tests, item)
+
+    def _writeElapsedTime(self, test):
+        color = get_elapsed_time_color(self.elapsed_time)
+        self.colorizer.write("  %.2f" % self.elapsed_time, color)
+
+    def _writeResult(self, test, long_result, color, short_result, success):
         if self.showAll:
-            self.colorizer.write("OK", 'green')
+            self.colorizer.write(long_result, color)
+            if self.show_elapsed and success:
+                self._writeElapsedTime(test)
             self.stream.writeln()
         elif self.dots:
-            self.stream.write('.')
+            self.stream.write(short_result)
             self.stream.flush()
 
     # NOTE(vish): copied from unittest with edit to add color
+    def addSuccess(self, test):
+        unittest.TestResult.addSuccess(self, test)
+        self._handleElapsedTime(test)
+        self._writeResult(test, 'OK', 'green', '.', True)
+
+    # NOTE(vish): copied from unittest with edit to add color
     def addFailure(self, test, err):
         unittest.TestResult.addFailure(self, test, err)
-        if self.showAll:
-            self.colorizer.write("FAIL", 'red')
-            self.stream.writeln()
-        elif self.dots:
-            self.stream.write('F')
-            self.stream.flush()
+        self._handleElapsedTime(test)
+        self._writeResult(test, 'FAIL', 'red', 'F', False)
 
     # NOTE(vish): copied from nose with edit to add color
     def addError(self, test, err):
@@ -226,6 +255,7 @@ class NovaTestResult(result.TextTestResult):
         errorClasses. If the exception is a registered class, the
         error will be added to the list for that class, not errors.
         """
+        self._handleElapsedTime(test)
         stream = getattr(self, 'stream', None)
         ec, ev, tb = err
         try:
@@ -252,14 +282,11 @@ class NovaTestResult(result.TextTestResult):
         self.errors.append((test, exc_info))
         test.passed = False
         if stream is not None:
-            if self.showAll:
-                self.colorizer.write("ERROR", 'red')
-                self.stream.writeln()
-            elif self.dots:
-                stream.write('E')
+            self._writeResult(test, 'ERROR', 'red', 'E', False)
 
     def startTest(self, test):
         unittest.TestResult.startTest(self, test)
+        self.start_time = time.time()
         current_case = test.test.__class__.__name__
 
         if self.showAll:
@@ -273,21 +300,47 @@ class NovaTestResult(result.TextTestResult):
 
 
 class NovaTestRunner(core.TextTestRunner):
+    def __init__(self, *args, **kwargs):
+        self.show_elapsed = kwargs.pop('show_elapsed')
+        core.TextTestRunner.__init__(self, *args, **kwargs)
+
     def _makeResult(self):
         return NovaTestResult(self.stream,
                               self.descriptions,
                               self.verbosity,
-                              self.config)
+                              self.config,
+                              show_elapsed=self.show_elapsed)
+
+    def _writeSlowTests(self, result_):
+        # Pare out 'fast' tests
+        slow_tests = [item for item in result_.slow_tests
+                      if get_elapsed_time_color(item[0]) != 'green']
+        if slow_tests:
+            slow_total_time = sum(item[0] for item in slow_tests)
+            self.stream.writeln("Slowest %i tests took %.2f secs:"
+                                % (len(slow_tests), slow_total_time))
+            for elapsed_time, test in sorted(slow_tests, reverse=True):
+                time_str = "%.2f" % elapsed_time
+                self.stream.writeln("    %s %s" % (time_str.ljust(10), test))
+
+    def run(self, test):
+        result_ = core.TextTestRunner.run(self, test)
+        if self.show_elapsed:
+            self._writeSlowTests(result_)
+        return result_
 
 
 if __name__ == '__main__':
     logging.setup()
     # If any argument looks like a test name but doesn't have "nova.tests" in
     # front of it, automatically add that so we don't have to type as much
+    show_elapsed = True
     argv = []
     for x in sys.argv:
         if x.startswith('test_'):
             argv.append('nova.tests.%s' % x)
+        elif x.startswith('--hide-elapsed'):
+            show_elapsed = False
         else:
             argv.append(x)
 
@@ -300,5 +353,6 @@ if __name__ == '__main__':
 
     runner = NovaTestRunner(stream=c.stream,
                             verbosity=c.verbosity,
-                            config=c)
+                            config=c,
+                            show_elapsed=show_elapsed)
     sys.exit(not core.run(config=c, testRunner=runner, argv=argv))
diff --git a/run_tests.sh b/run_tests.sh
index c7bcd5d67..c3f06f837 100755
--- a/run_tests.sh
+++ b/run_tests.sh
@@ -10,6 +10,7 @@ function usage {
   echo "  -f, --force              Force a clean re-build of the virtual environment. Useful when dependencies have been added."
   echo "  -p, --pep8               Just run pep8"
   echo "  -h, --help               Print this usage message"
+  echo "  --hide-elapsed           Don't print the elapsed time for each test along with slow test list"
   echo ""
   echo "Note: with no options specified, the script will try to run the tests in a virtual environment,"
   echo "      If no virtualenv is found, the script will ask if you would like to create one.  If you "
@@ -24,6 +25,7 @@ function process_option {
     -N|--no-virtual-env) let always_venv=0; let never_venv=1;;
     -f|--force) let force=1;;
     -p|--pep8) let just_pep8=1;;
+    -*) noseopts="$noseopts $1";;
     *) noseargs="$noseargs $1"
   esac
 }
@@ -34,6 +36,7 @@ always_venv=0
 never_venv=0
 force=0
 noseargs=
+noseopts=
 wrapper=""
 just_pep8=0
 
@@ -72,7 +75,7 @@ function run_pep8 {
   --exclude=vcsversion.py ${srcfiles}
 }
 
-NOSETESTS="python run_tests.py $noseargs"
+NOSETESTS="python run_tests.py $noseopts $noseargs"
 
 if [ $never_venv -eq 0 ]
 then
@@ -107,7 +110,10 @@ fi
 
 run_tests || exit
 
-# Also run pep8 if no options were provided.
+# NOTE(sirp): we only want to run pep8 when we're running the full-test suite,
+# not when we're running tests individually. To handle this, we need to
+# distinguish between options (noseopts), which begin with a '-', and
+# arguments (noseargs).
 if [ -z "$noseargs" ]; then
   run_pep8
 fi