Time what happens when running tests and optionally report

1 files changed, 37 insertions, 2 deletions

diff --git a/cmdtest b/cmdtest
index 4d89eea..d2889d7 100755
--- a/cmdtest
+++ b/cmdtest
@@ -22,12 +22,17 @@ import os
 import shutil
 import sys
 import tempfile
+import time
 import ttystatus
 import unittest
 
 import cmdtestlib
 
 
+ALL_TESTS = ''
+COMPLETE_TEST = ''
+
+
 class TestFailure(Exception):
 
     def __init__(self, test, msg):
@@ -45,17 +50,24 @@ class CommandTester(cliapp.Application):
         self.settings.string_list(['test', 't'],
                                   'run only TEST (can be given many times)',
                                   metavar='TEST')
+        self.settings.boolean(['timings'], 'report how long each test takes')
 
     def process_args(self, dirnames):
         self.setup_ttystatus()
 
         td = self.load_tests(dirnames)
         self.ts['tests'] = td.tests
+        
+        self.timings = {}
+        self.timings[ALL_TESTS] = {}
+        suite_started = time.time()
 
         errors = 0
         self.setup_tempdir()
-        self.run_script('', td.setup_once)
+        self.run_script(ALL_TESTS, td.setup_once)
         for test in td.tests:
+            self.timings[test.name] = {}
+            started = time.time()
             self.ts['test'] = test.name
             self.run_script(test.name, td.setup)
             for e in self.run_test(test):
@@ -64,13 +76,19 @@ class CommandTester(cliapp.Application):
                 self.output.write('%s\n' % str(e))
                 errors += 1
             self.run_script(test.name, td.teardown)
-        self.run_script('', td.teardown_once)
+            self.timings[test.name][COMPLETE_TEST] = time.time() - started
+        self.run_script(ALL_TESTS, td.teardown_once)
         self.cleanup_tempdir()
+        self.timings[ALL_TESTS][COMPLETE_TEST] = time.time() - suite_started
                 
         ok = len(td.tests) - errors
         self.ts.finish()
         self.output.write('%d/%d tests OK, %d failures\n' % 
                             (ok, len(td.tests), errors))
+
+        if self.settings['timings']:
+            self.report_timings()
+
         if errors:
             sys.exit(1)
 
@@ -109,7 +127,9 @@ class CommandTester(cliapp.Application):
         logging.debug('run_script: test_name=%s script_name=%s' %
                       (test_name, script_name))
         if script_name:
+            started = time.time()
             self.runcmd([script_name], env=self.add_to_env(test_name))
+            self.timings[test_name][script_name] = time.time() - started
 
     def add_to_env(self, test_name):
         env = dict(os.environ)
@@ -201,6 +221,21 @@ class CommandTester(cliapp.Application):
         with open(filename, 'w') as f:
             f.write(content)
 
+    def report_timings(self):
+
+        def report(key, title):
+            t = self.timings[key]
+            self.output.write('  %s: %.1f s\n' % (title, t[COMPLETE_TEST]))
+            
+            items = [(t[x], x) for x in t.keys() if x != COMPLETE_TEST]
+            for secs, script in sorted(items):
+                self.output.write('    %4.1f %s\n' % (secs, script))
+                
+        self.output.write('Timings (in seconds):\n')
+        report(ALL_TESTS, 'whole test suite')
+        for name in sorted(x for x in self.timings.keys() if x != ALL_TESTS):
+            report(name, name)
+
 
 if __name__ == '__main__':
     CommandTester(version=cmdtestlib.__version__).run()