test: further improve test suite time display

Perhaps I obsessed about this output a bit too much?
It *does* like nicer and more useful now.

2 files changed, 55 insertions, 31 deletions

diff --git a/test/harness/tests.py b/test/harness/tests.py
index 224f216..2adad04 100644
--- a/test/harness/tests.py
+++ b/test/harness/tests.py
@@ -5,12 +5,41 @@ tests -- the actual TestCase (just one)
 import sys
 import os
 import unittest
+import time
 
 from . import util
 from .util import Global
 from .iscsi import IscsiData
 
 
+def s2dt(s):
+    # seconds to "HH:MM:SS.sss"
+    s_orig = s
+    hrs = s / 3600
+    s -= (int(hrs) * 3600)
+    mins = s / 60
+    s -= (int(mins) * 60)
+    a_str="%02d:%02d:%06.3f" % (hrs, mins, s)
+    dprint("s2dt: %f -> %s" % (s_orig, a_str))
+    return a_str
+
+
+def print_time_values():
+    # print out global exec time values
+    util.vprint('')
+    util.vprint('Times spent running sub-programs:')
+    ttl_time = 0.0
+    for s in Global.timing.keys():
+        v = Global.timing[s]
+        r = s2dt(v)
+        ttl_time += v
+        util.vprint('  %10s = %s' % (s, r))
+    util.vprint('    =======================')
+    util.vprint('  %10s = %s' % ('Total', s2dt(ttl_time)))
+    util.vprint('')
+    util.vprint('Total test-run time: %s' % (s2dt(Global.total_time)))
+
+
 class TestRegression(unittest.TestCase):
     """
     Regression testing
@@ -38,6 +67,7 @@ class TestRegression(unittest.TestCase):
                             [4096, 4096, 32768],
                             [4096, 4096, 65536],
                             [4096, 4096, 131072]]
+        cls.time_start = time.perf_counter()
 
     def setUp(self):
         if Global.debug or Global.verbosity > 1:
@@ -177,7 +207,5 @@ class TestRegression(unittest.TestCase):
                       '-T', Global.target,
                       '-p', Global.ipnr,
                       '--logout'])
-        util.vprint("Times: fio=%-.3f, sgdisk=%-.3f, dd=%-.3f, bonnie=%-.3f, mkfs=%-.3f, sleep=%-.3f" % \
-                (Global.fio_time, Global.sgdisk_time, Global.dd_time, \
-                 Global.bonnie_time, Global.mkfs_time, Global.sleep_time))
-
+        Global.total_time = time.perf_counter() - cls.time_start
+        print_time_values()
diff --git a/test/harness/util.py b/test/harness/util.py
index d7c64a2..fd09d67 100644
--- a/test/harness/util.py
+++ b/test/harness/util.py
@@ -43,12 +43,8 @@ class Global:
     # no good way to detect that.
     subtest_list = [i+1 for i in range(16)]
     # for timing
-    fio_time = 0.0
-    sgdisk_time = 0.0
-    dd_time = 0.0
-    bonnie_time = 0.0
-    mkfs_time = 0.0
-    sleep_time = 0.0
+    timing = dict.fromkeys(['fio', 'sgdisk', 'dd', 'bonnie', 'mkfs', 'sleep'], 0.0)
+    total_time = 0.0
 
 
 def dprint(*args):
@@ -285,7 +281,7 @@ def run_fio():
             direct=1
         else:
             direct=0
-        ts = time.time()
+        ts = time.perf_counter()
         res = run_cmd(['fio', '--name=read-test', '--readwrite=randread',
             '--runtime=2s', '--numjobs=8', '--blocksize=%s' % bs, 
             '--offset=256k',
@@ -305,8 +301,8 @@ def run_fio():
             '--verify=md5', '--verify_state_save=0'])
         if res != 0:
             return (res, 'fio failed')
-        te = time.time()
-        Global.fio_time += (te - ts)
+        te = time.perf_counter()
+        Global.timing['fio'] += te - ts
     return (0, 'Success')
 
 def wait_for_path(path, present=True, amt=10):
@@ -330,26 +326,26 @@ def wipe_disc():
     # zero out the label and parition table
     vprint('Running "sgdisk" and "dd" to wipe disc label, partitions, and filesystem')
     sleep_some(1)
-    ts = time.time()
+    ts = time.perf_counter()
     res = run_cmd(['sgdisk', '--clear', Global.device])
-    te = time.time()
-    Global.sgdisk_time += (te - ts)
+    te = time.perf_counter()
+    Global.timing['sgdisk'] += te -ts
     if res != 0:
         if res == 4:
             dprint("Oh oh -- 'clear' failed! trying one more time ...")
-        ts = time.time()
+        ts = time.perf_counter()
         res = run_cmd(['sgdisk', '--clear', Global.device])
-        te = time.time()
+        te = time.perf_counter()
         if res != 0:
             return (res, '%s: could not zero out label after two tries: %d' % \
                     (Global.device, res))
-        Global.sgdisk_time += (te - ts)
-    ts = time.time()
+        Global.timing['sgdisk'] += te - ts
+    ts = time.perf_counter()
     res = run_cmd(['dd', 'if=/dev/zero', 'of=%s' % Global.device, 'bs=256k', 'count=20', 'oflag=direct'])
-    te = time.time()
+    te = time.perf_counter()
     if res != 0:
         return (res, '%s: could not zero out filesystem: %d' % (Global.device, res))
-    Global.dd_time += (te - ts)
+    Global.timing['dd'] += te - ts
     return (0, 'Success')
     
 def run_parted():
@@ -384,12 +380,12 @@ def run_parted():
 
 def run_mkfs():
     vprint('Running "mkfs" to to create filesystem')
-    ts = time.time()
+    ts = time.perf_counter()
     res = run_cmd(Global.MKFSCMD + [ Global.partition ] )
-    te = time.time()
+    te = time.perf_counter()
     if res != 0:
         return (res, '%s: mkfs failed (%d)' % (Global.partition, res))
-    Global.mkfs_time += (te - ts)
+    Global.timing['mkfs'] += te - ts
     return (0, 'Success')
 
 def run_bonnie():
@@ -401,12 +397,12 @@ def run_bonnie():
             return (res, '%s: mount failed (%d)' % (Global.partition, res))
         # run bonnie++ on the new directory
         vprint('Running "bonnie++" on the filesystem')
-        ts = time.time()
+        ts = time.perf_counter()
         res = run_cmd(['bonnie++'] + Global.BONNIEPARAMS + ['-d', tmp_dir])
-        te = time.time()
+        te = time.perf_counter()
         if res != 0:
             return (res, '%s: umount failed (%d)' % (tmp_dir, res))
-        Global.bonnie_time += (te - ts)
+        Global.timing['bonnie'] += te - ts
         # unmount the device and remove the temp dir
         vprint('Running "umount" to unmount the filesystem')
         res = run_cmd(['umount', tmp_dir])
@@ -416,7 +412,7 @@ def run_bonnie():
 
 def sleep_some(s):
     # sleep s seconds
-    ts = time.time()
+    ts = time.perf_counter()
     time.sleep(s)
-    te = time.time()
-    Global.sleep_time += (te - ts)
+    te = time.perf_counter()
+    Global.timing['sleep'] += te - ts