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

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)
 
+    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(long_result, color)
+            if self.show_elapsed and success:
+                self._writeElapsedTime(test)
+            self.stream.writeln()
+        elif self.dots:
+            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)
-        if self.showAll:
+        self._handleElapsedTime(test)
-            self.colorizer.write("OK", 'green')
+        self._writeResult(test, 'OK', 'green', '.', True)
-            self.stream.writeln()
-        elif self.dots:
-            self.stream.write('.')
-            self.stream.flush()
 
     # 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._handleElapsedTime(test)
-            self.colorizer.write("FAIL", 'red')
+        self._writeResult(test, 'FAIL', 'red', 'F', False)
-            self.stream.writeln()
-        elif self.dots:
-            self.stream.write('F')
-            self.stream.flush()
 
     # 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._writeResult(test, 'ERROR', 'red', 'E', False)
-                self.colorizer.write("ERROR", 'red')
-                self.stream.writeln()
-            elif self.dots:
-                stream.write('E')
 
     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))