misc: Add memory usage information to run_tests output.

misc/regression/memusage.py

@@ -0,0 +1,106 @@
+#!/usr/bin/env python
+#
+#
+# Copyright 2014, NICTA
+#
+# This software may be distributed and modified according to the terms of
+# the BSD 2-Clause license. Note that NO WARRANTY is provided.
+# See "LICENSE_BSD2.txt" for details.
+#
+# @TAG(NICTA_BSD)
+#
+
+'''
+Monitors the peak memory usage of a process and its children. Usage is similar
+to the UNIX `time` utility.
+'''
+import psutil, subprocess, sys, threading, time
+
+def get_usage(proc):
+    '''Retrieve the memory usage of a particular psutil process without its
+    children. We use the proportional set size, which accounts for shared pages
+    to give us a more accurate total usage.'''
+    assert isinstance(proc, psutil.Process)
+    return sum([m.pss for m in proc.get_memory_maps(grouped=True)])
+
+def get_total_usage(pid):
+    '''Retrieve the memory usage of a process by PID including its children. We
+    ignore NoSuchProcess errors to mask subprocesses exiting while the cohort
+    continues.'''
+    total = 0
+    try:
+        p = psutil.Process(pid)
+        total += get_usage(p)
+    except psutil.NoSuchProcess:
+        return 0
+    for proc in p.get_children(recursive=True): #pylint: disable=E1123
+        try:
+            total += get_usage(proc)
+        except psutil.NoSuchProcess:
+            pass
+    return total
+
+class Poller(threading.Thread):
+    def __init__(self, pid):
+        super(Poller, self).__init__()
+        # Daemonise ourselves to avoid delaying exit of the process of our
+        # calling thread.
+        self.daemon = True
+        self.pid = pid
+        self.high = 0
+        self.finished = False
+
+    def run(self):
+        self.high = 0
+        # Poll the process once a second and track a high water mark of its
+        # memory usage.
+        while not self.finished:
+            usage = get_total_usage(self.pid)
+            if usage > self.high:
+                self.high = usage
+            time.sleep(1)
+
+    def peak_mem_usage(self):
+        return self.high
+
+    def __enter__(self):
+        return self
+
+    def __exit__(self, *_):
+        self.finished = True
+
+def process_poller(pid):
+    '''Initiate polling of a subprocess. This is intended to be used in a
+    `with` block.'''
+    p = Poller(pid)
+    p.start()
+    return p
+
+def main():
+    if len(sys.argv) <= 1 or sys.argv[1] in ['-?', '--help']:
+        print >>sys.stderr, 'Usage: %s command args...\n Measure peak memory ' \
+            'usage of a command' % sys.argv[0]
+        return -1
+
+    # Run the command requested.
+    try:
+        p = subprocess.Popen(sys.argv[1:])
+    except OSError:
+        print >>sys.stderr, 'command not found'
+        return -1
+
+    high = 0
+    try:
+        with process_poller(p.pid) as m: #pylint: disable=E1101
+            p.communicate()
+            high = m.peak_mem_usage()
+    except KeyboardInterrupt:
+        # The user Ctrl-C-ed us. Fake an error return code.
+        p.returncode = -1
+
+    print >>sys.stderr, 'Peak usage %d bytes' % high
+
+    return p.returncode
+
+if __name__ == '__main__':
+    sys.exit(main())

misc/regression/run_tests.py

@@ -21,6 +21,7 @@ import argparse
 import atexit
 import datetime
 import fnmatch
+import memusage
 import os
 import signal
 import subprocess
@@ -103,7 +104,7 @@ def kill_family(parent_pid):
 #
 # Run a single test.
 #
-# Return a tuple of (success, log, time_taken).
+# Return a tuple of (success, log, time_taken, memory_usage).
 #
 # Log only contains the output if verbose is *false*; otherwise, the
 # log is output to stdout where we can't easily get  to it.
@@ -135,6 +136,7 @@ def run_test(test, verbose=False):
     start_time = datetime.datetime.now()
 
     # Start the command.
+    usage = None
     try:
         process = subprocess.Popen(command,
                 stdout=output, stderr=subprocess.STDOUT, stdin=subprocess.PIPE,
@@ -143,7 +145,7 @@ def run_test(test, verbose=False):
         output = "Exception while running test:\n\n%s" % (traceback.format_exc())
         if verbose:
             print(output)
-        return (False, "ERROR", output, datetime.datetime.now() - start_time)
+        return (False, "ERROR", output, datetime.datetime.now() - start_time, usage)
 
     # If our program exits for some reason, attempt to kill the process.
     atexit.register(lambda: kill_family(process.pid))
@@ -157,7 +159,9 @@ def run_test(test, verbose=False):
     signal.alarm(test.timeout)
 
     # Wait for the command to finish.
-    (output, _) = process.communicate()
+    with memusage.process_poller(process.pid) as m:
+        (output, _) = process.communicate()
+        usage = m.peak_mem_usage()
 
     # Cancel the alarm. Small race here (if the alarm fires just after the
     # process finished), but the returncode of our process should still be 0,
@@ -172,27 +176,31 @@ def run_test(test, verbose=False):
         status = "TIMEOUT"
     else:
         status = "FAILED"
-    return (process.returncode == 0, status, output, datetime.datetime.now() - start_time)
+    return (process.returncode == 0, status, output, datetime.datetime.now() - start_time, usage)
 
 # Print a status line.
 def print_test_line_start(test_name):
     print("  running %-25s " % (test_name + " ..."), end="")
     sys.stdout.flush()
 
-def print_test_line_end(test_name, color, status, time_taken):
+def print_test_line_end(test_name, color, status, time_taken, mem):
+    if mem:
+        # Report meory usage in gigabytes.
+        mem = '%.2fGB' % round(float(mem) / 1024 / 1024 / 1024, 2)
     if time_taken:
         # Strip milliseconds for better printing.
         time_taken = datetime.timedelta(seconds=int(time_taken.total_seconds()))
+        time_taken = '%8s' % time_taken
+    extras = ', '.join(filter(None, [time_taken, mem]))
+
+    # Print status line.
+    print(output_color(color, "%-10s" % status) + ('(%s)' % extras if extras else ''))
 
-        # Print status line.
-        print(output_color(color, "%-10s" % status) + (" %8s" % ("(" + str(time_taken) + ")")))
-    else:
-        print(output_color(color, "%-10s" % status))
     sys.stdout.flush()
 
-def print_test_line(test_name, color, status, time_taken):
+def print_test_line(test_name, color, status, time_taken, mem):
     print_test_line_start(test_name)
-    print_test_line_end(test_name, color, status, time_taken)
+    print_test_line_end(test_name, color, status, time_taken, mem)
 
 #
 # Recursive glob
@@ -270,21 +278,21 @@ def main():
     failed_test_log = []
     for t in tests_to_run:
         if len(t.depends & failed_tests) > 0:
-            print_test_line(t.name, ANSI_YELLOW, "skipped", None)
+            print_test_line(t.name, ANSI_YELLOW, "skipped", None, None)
             failed_tests.add(t.name)
             continue
 
         # Run the test.
         print_test_line_start(t.name)
-        (passed, status, log, time_taken) = run_test(t, verbose=args.verbose)
+        (passed, status, log, time_taken, mem) = run_test(t, verbose=args.verbose)
 
         # Print result.
         if not passed:
             failed_tests.add(t.name)
             failed_test_log.append((t.name, log, time_taken))
-            print_test_line_end(t.name, ANSI_RED, "%s *" % status, time_taken)
+            print_test_line_end(t.name, ANSI_RED, "%s *" % status, time_taken, mem)
         else:
-            print_test_line_end(t.name, ANSI_GREEN, status, time_taken)
+            print_test_line_end(t.name, ANSI_GREEN, status, time_taken, mem)
 
     # Print failure summaries unless requested not to.
     if not args.brief and len(failed_test_log) > 0: