From bd77739de689db3839437a9c035c6eca7894f27e Mon Sep 17 00:00:00 2001 From: Lee Duncan Date: Wed, 2 Mar 2022 14:50:04 -0800 Subject: 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. --- test/harness/tests.py | 36 ++++++++++++++++++++++++++++++++---- test/harness/util.py | 50 +++++++++++++++++++++++--------------------------- 2 files changed, 55 insertions(+), 31 deletions(-) (limited to 'test') 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 -- cgit v1.2.1