diff --git a/misc/regression/memusage.py b/misc/regression/memusage.py new file mode 100644 index 000000000..381522206 --- /dev/null +++ b/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()) diff --git a/misc/regression/run_tests.py b/misc/regression/run_tests.py index 70a28e328..9fd0e5ad4 100755 --- a/misc/regression/run_tests.py +++ b/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: