test.py: Make output pretty and show duration

Make the test runner output look pretty and show test duration to make
it visible which tests take the longest time to run.  The output looks
as follows now:

    TEST tst-af-local.so           OK  (3.288 s)
    TEST tst-bdev-write.so         OK  (1.058 s)
    TEST tst-bsd-evh.so            OK  (1.071 s)
    TEST tst-bsd-kthread.so        OK  (1.234 s)
    TEST tst-bsd-taskqueue.so      OK  (1.062 s)
    TEST tst-bsd-tcp1.so           OK  (2.114 s)
    TEST tst-commands.so           OK  (1.141 s)
    TEST tst-condvar.so            OK  (1.776 s)
    TEST tst-dns-resolver.so       OK  (2.560 s)
    TEST tst-epoll.so              OK  (1.952 s)
    TEST tst-except.so             OK  (1.146 s)
    TEST tst-fpu.so                OK  (2.630 s)
    TEST tst-fs-link.so            OK  (1.051 s)
    TEST tst-fs-stress.so          OK  (1.027 s)
    TEST tst-fsx.so                OK  (1.067 s)
    TEST tst-hub.so                OK  (6.256 s)
    TEST tst-huge.so               OK  (2.199 s)
    TEST tst-kill.so               OK  (4.147 s)
    TEST tst-libc-locking.so       OK  (2.110 s)
    TEST tst-loadbalance.so        OK  (1.070 s)
    TEST tst-mmap-file.so          OK  (1.080 s)
    TEST tst-mmap.so               OK  (1.087 s)
    TEST tst-pipe.so               OK  (7.306 s)
    TEST tst-preempt.so            OK  (1.119 s)
    TEST tst-pthread.so            OK  (1.100 s)
    TEST tst-queue-mpsc.so         OK  (3.748 s)
    TEST tst-ramdisk.so            OK  (1.078 s)
    TEST tst-readdir.so            OK  (1.094 s)
    TEST tst-remove.so             OK  (1.030 s)
    TEST tst-rename.so             OK  (1.157 s)
    TEST tst-resolve.so            OK  (1.095 s)
    TEST tst-scheduler.so          OK  (1.087 s)
    TEST tst-sleep.so              OK  (3.083 s)
    TEST tst-solaris-taskq.so      OK  (1.061 s)
    TEST tst-stat.so               OK  (1.106 s)
    TEST tst-strerror_r.so         OK  (1.102 s)
    TEST tst-tcp-sendonly.so       OK  (2.014 s)
    TEST tst-tcp.so                OK  (1.080 s)
    TEST tst-threadcomplete.so     OK  (2.770 s)
    TEST tst-tracepoint.so         OK  (1.109 s)
    TEST tst-truncate.so           OK  (1.083 s)
    TEST tst-utimes.so             OK  (1.079 s)
    TEST tst-vblk.so               OK  (1.310 s)
    TEST tst-vfs.so                OK  (1.118 s)
    TEST tst-yield.so              OK  (1.992 s)
    TEST tst-zfs-mount.so          OK  (1.087 s)
  OK (58 tests run, 82.944 s)

Reviewed-by: Nadav Har'El <nyh@cloudius-systems.com>
Signed-off-by: Pekka Enberg <penberg@cloudius-systems.com>

scripts/test.py

@@ -2,6 +2,7 @@
 import subprocess
 import argparse
 import glob
+import time
 import sys
 import os
 import re
@@ -38,7 +39,10 @@ def scan_errors(s):
     return False
 
 def run_test(name):
-    print("Running '%s'..." % name)
+    sys.stdout.write("  TEST %-25s" % name)
+    sys.stdout.flush()
+
+    start = time.time()
     args = ["-g", "-e", "tests/%s" % (name)]
     process = subprocess.Popen(["./scripts/run.py"] + args, stdout=subprocess.PIPE)
     out = ""
@@ -59,16 +63,28 @@ def run_test(name):
                 cmdargs.verbose = True
             line = ""
 
+    end = time.time()
+
     if scan_errors(out) or process.returncode:
-        print("Test '%s' FAILED" % name)
+        sys.stdout.write("Test %s FAILED\n" % name)
+        sys.stdout.flush()
         exit(1)
+    else:
+        duration = end - start
+        sys.stdout.write(" OK  (%.3f s)\n" % duration)
+        sys.stdout.flush()
 
 def run_tests():
+    start = time.time()
+
     for test in tests:
         if not test in blacklist:
             run_test(test)
 
-    print("OK (%d tests run)" % (len(tests)))
+    end = time.time()
+
+    duration = end - start
+    print("OK (%d tests run, %.3f s)" % (len(tests), duration))
 
 def main():
     run_tests()