test: Track time spent calling subprocesses

Track how long it takes to run subprocesses
like bonnie++ and fio, and print the result
at test-end time if in verbose mode.

Time is measured using time.time(), so not
overly accurate -- just adds some information.

2 files changed, 43 insertions, 11 deletions

diff --git a/test/harness/tests.py b/test/harness/tests.py
index c13c80c..b49bd3f 100644
--- a/test/harness/tests.py
+++ b/test/harness/tests.py
@@ -151,12 +151,16 @@ class TestRegression(unittest.TestCase):
         # wait a few seconds for the device to show up
         if not util.wait_for_path(Global.device):
             self.fail('%s: does not exist after login' % Global.device)
-        (res, reason) = util.run_fio()
-        self.assertEqual(res, 0, reason)
+        # run parted to partition the disc with one whole disk partition
         (res, reason) = util.run_parted()
         self.assertEqual(res, 0, reason)
+        # run fio to test file IO
+        (res, reason) = util.run_fio()
+        self.assertEqual(res, 0, reason)
+        # make a filesystem
         (res, reason) = util.run_mkfs()
         self.assertEqual(res, 0, reason)
+        # run bonnie++ to test the filesystem IO
         (res, reason) = util.run_bonnie()
         self.assertEqual(res, 0, reason)
 
@@ -170,4 +174,6 @@ class TestRegression(unittest.TestCase):
                       '-T', Global.target,
                       '-p', Global.ipnr,
                       '--logout'])
+        util.vprint("Times: fio=%-5.3f, sgdisk=%-5.3f, dd=%-5.3f, bonnie=%-5.3f" % \
+                (Global.fio_time, Global.sgdisk_time, Global.dd_time, Global.bonnie_time))
 
diff --git a/test/harness/util.py b/test/harness/util.py
index 06636b3..0e00592 100644
--- a/test/harness/util.py
+++ b/test/harness/util.py
@@ -42,6 +42,11 @@ class Global:
     # XXX we should really look how many subtests there are, but there's
     # 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
 
 
 def dprint(*args):
@@ -261,7 +266,7 @@ def run_fio():
     Return zero for success.
     Return non-zero for failure and a failure reason.
 
-    Uses Globals: device, blocksize
+    Uses Globals: partition, blocksize
     """
     if Global.blocksize is not None:
         dprint('Found a block size passed in: %s' % Global.blocksize)
@@ -272,30 +277,34 @@ def run_fio():
                 '16k', '32k', '75536', '128k', '1000000']
     # for each block size, do a read test, then a write test
     for bs in blocksizes:
-        vprint('Running "fio" read test: 8 threads, bs=%s' % bs)
+        vprint('Running "fio" read/write/verify tests with 8/8/1 threads, bs=%s' % bs)
         # only support direct IO with aligned reads
         if bs.endswith('k'):
             direct=1
         else:
             direct=0
+        ts = time.time()
         res = run_cmd(['fio', '--name=read-test', '--readwrite=randread',
             '--runtime=2s', '--numjobs=8', '--blocksize=%s' % bs, 
-            '--direct=%d' % direct, '--filename=%s' % Global.device])
+            '--offset=256k',
+            '--direct=%d' % direct, '--filename=%s' % Global.partition])
         if res != 0:
             return (res, 'fio failed')
-        vprint('Running "fio" write test: 8 threads, bs=%s' % bs)
         res = run_cmd(['fio', '--name=write-test', '--readwrite=randwrite',
             '--runtime=2s', '--numjobs=8', '--blocksize=%s' % bs, 
-            '--direct=%d' % direct, '--filename=%s' % Global.device])
+            '--offset=256k',
+            '--direct=%d' % direct, '--filename=%s' % Global.partition])
         if res != 0:
             return (res, 'fio failed')
-        vprint('Running "fio" verify test: 1 thread, bs=%s' % bs)
         res = run_cmd(['fio', '--name=verify-test', '--readwrite=randwrite',
             '--runtime=2s', '--numjobs=1', '--blocksize=%s' % bs, 
-            '--direct=%d' % direct, '--filename=%s' % Global.device,
+            '--direct=%d' % direct, '--filename=%s' % Global.partition,
+            '--offset=256k',
             '--verify=md5', '--verify_state_save=0'])
         if res != 0:
             return (res, 'fio failed')
+        te = time.time()
+        Global.fio_time += (te - ts)
     return (0, 'Success')
 
 def wait_for_path(path, present=True, amt=10):
@@ -319,12 +328,26 @@ def wipe_disc():
     # zero out the label and parition table
     vprint('Running "sgdisk" and "dd" to wipe disc label, partitions, and filesystem')
     time.sleep(1)
-    res = run_cmd(['sgdisk', '-Z', Global.device])
+    ts = time.time()
+    res = run_cmd(['sgdisk', '--clear', Global.device])
+    te = time.time()
+    Global.sgdisk_time += (te - ts)
     if res != 0:
-        return (res, '%s: could not zero out label: %d' % (Global.device, res))
+        if res == 4:
+            dprint("Oh oh -- 'clear' failed! trying one more time ...")
+        ts = time.time()
+        res = run_cmd(['sgdisk', '--clear', Global.device])
+        te = time.time()
+        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()
     res = run_cmd(['dd', 'if=/dev/zero', 'of=%s' % Global.device, 'bs=256k', 'count=20', 'oflag=direct'])
+    te = time.time()
     if res != 0:
         return (res, '%s: could not zero out filesystem: %d' % (Global.device, res))
+    Global.dd_time += (te - ts)
     return (0, 'Success')
     
 def run_parted():
@@ -373,9 +396,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()
         res = run_cmd(['bonnie++'] + Global.BONNIEPARAMS + ['-d', tmp_dir])
+        te = time.time()
         if res != 0:
             return (res, '%s: umount failed (%d)' % (tmp_dir, res))
+        Global.bonnie_time += (te - ts)
         # unmount the device and remove the temp dir
         vprint('Running "unmount" to unmount the filesystem')
         res = run_cmd(['umount', tmp_dir])