Switch to elapsed time in subunit-trace summary

This commit switches the time output to the elapsed time instead of
the total time in the results summary at the end of subunit-trace.
This is accomplished by just measuring the time delta right before
we begin processing the result stream until right after. While this
is not the most accurate method to measure the elapsed time, it
should be sufficient.

Previously just the total time was shown which could be misleading
since it is just the sum of the execute time for the individual test
methods (excluding the test fixtures). When running in parallel this
number would usually be a fair bit larger than the elapsed time of the
test run. By using the elapsed time instead it makes it easier to track
the performance of the run.

Change-Id: I7a1113c7f1333389b1b42249cafc4a45d630cb9f

tempest_lib/cmd/subunit_trace.py

@@ -19,6 +19,7 @@
 """Trace a subunit stream in reasonable detail and high accuracy."""
 
 import argparse
+import datetime
 import functools
 import re
 import sys
@@ -186,13 +187,14 @@ def worker_stats(worker):
     return num_tests, delta
 
 
-def print_summary(stream):
+def print_summary(stream, elapsed_time):
     stream.write("\n======\nTotals\n======\n")
-    stream.write("Run: %s in %s sec.\n" % (count_tests('status', '.*'),
-                                           run_time()))
+    stream.write("Ran: %s tests in %.4f sec.\n" % (
+        count_tests('status', '.*'), elapsed_time.total_seconds()))
     stream.write(" - Passed: %s\n" % count_tests('status', 'success'))
     stream.write(" - Skipped: %s\n" % count_tests('status', 'skip'))
     stream.write(" - Failed: %s\n" % count_tests('status', 'fail'))
+    stream.write("Sum of execute time for each test: %.4f sec.\n" % run_time())
 
     # we could have no results, especially as we filter out the process-codes
     if RESULTS:
@@ -229,17 +231,21 @@ def main():
                           print_failures=args.print_failures))
     summary = testtools.StreamSummary()
     result = testtools.CopyStreamResult([outcomes, summary])
+    start_time = datetime.datetime.utcnow()
     result.startTestRun()
     try:
         stream.run(result)
     finally:
         result.stopTestRun()
+    stop_time = datetime.datetime.utcnow()
+    elapsed_time = stop_time - start_time
+
     if count_tests('status', '.*') == 0:
         print("The test run didn't actually run any tests")
         exit(1)
     if args.post_fails:
         print_fails(sys.stdout)
-    print_summary(sys.stdout)
+    print_summary(sys.stdout, elapsed_time)
     exit(0 if summary.wasSuccessful() else 1)