#!/usr/bin/env python """ runbench.py [options] [benchname1.py] [benchname2.py] measure memory usage for given benchmarks (or all if none specified). and append results to a log file ("bench.log" by default). """ import os, sys, re from subprocess import Popen, PIPE import py import smaps import time optparse = py.compat.optparse mydir = py.magic.autopath().dirpath() benchmarkdir = mydir.join("benchmark") class BenchRunner: SEPBENCH = "=" * 80 HEADERSEP = "HEADER" def __init__(self, executable, logpath, options): self.executable = executable self.executable_full_path = py.path.local.sysfind(executable) assert self.executable_full_path self.logpath = py.path.local(logpath) self.logstream = self.logpath.open("a") self.options = options self.tmpdir = py.path.local.make_numbered_dir(prefix="bench") def getbenchsource(self): preamble = """ import sys sys.path.insert(0, %r) """ % (str(benchmarkdir), ) return py.code.Source(preamble, self.benchpath.read()) def getnames(self): l = [] for name, obj in vars(self.benchpath.pyimport()).items(): if name.startswith("bench") and callable(obj): l.append(name) l.sort() return l def write_benchheader(self, benchname, args): print >>self.logstream, self.SEPBENCH print >>self.logstream, "#benchtype=%s" % (self.benchtype,) print >>self.logstream, "#executable=%s" %(str(self.executable ),) print >>self.logstream, "#benchpath=%s" %(self.benchpath.basename,) print >>self.logstream, "#benchname=%s" %(benchname,) print >>self.logstream, "#benchargs=%s" %(args,) print >>self.logstream def write_internal_header(self, kw): print >>self.logstream, self.HEADERSEP for name, value in kw.items(): print >>self.logstream, "#%s=%s" % (name, value) print >>self.logstream def log(self, *args): benchtype = getattr(self, 'benchtype', '?') executable = getattr(self, 'executable', '?') print "%s/%s: %s" %(executable, benchtype, " ".join(map(str, args))) class BenchRunnerBaseSize(BenchRunner): def write_benchheader(self): print >>self.logstream, self.SEPBENCH print >>self.logstream, "#benchtype=basesize" print >>self.logstream, "#executable=%s" %(str(self.executable ),) print >>self.logstream def run(self): cmds = [str(self.executable_full_path), '-S', '-c', '''import sys; sys.stdout.write("F"); sys.stdout.flush(); raw_input()'''] self.log("running %r" % (cmds, )) popen = Popen(cmds, shell=False, stdin=PIPE, stdout=PIPE, close_fds=True) self.write_benchheader() rec = smaps.SmapsRecorder(popen.pid, self.logstream) #print "Reading", popen.pid line = popen.stdout.read(1).strip() assert line == 'F' rec.snapshot() #print "Writing" popen.stdin.write("\n") popen.stdin.flush() #print "Waiting" popen.wait() def get_result(txt, pattern): for line in txt.split('\n'): if line.startswith(pattern): break else: print 'warning: this is no valid output' return 99999.0 return float(line.split()[len(pattern.split())]) class TimeRunner(BenchRunner): # abstract def __init__(self, executable, logpath, options): BenchRunner.__init__(self, executable, logpath, options) def write_benchheader(self, benchtype): print >>self.logstream, self.SEPBENCH print >>self.logstream, "#benchtype=" + benchtype print >>self.logstream, "#executable=%s" %(str(self.executable ),) print >>self.logstream def timecommand(self, cmd, pathstr="", pattern=None): env = {"PYTHONSTARTUP": "", "PYTHONPATH": pathstr} cmds = "time -p " + cmd self.log("running %r for %i times" % (cmds, self.numiter)) alltimes = [] for _ in xrange(self.numiter): popen = Popen(cmds, shell=True, stdout=PIPE, stderr=PIPE, close_fds=True, env=env) if popen.wait(): print "ERROR in command", cmds output_error = popen.stderr.read() print "stderr:", output_error continue output = popen.stdout.read() output_error = popen.stderr.read() timelines = output_error.strip().splitlines()[-3:] times = {} if pattern is not None: result = get_result(output, pattern) times["perf"] = result for line in timelines: name, time = line.split(" ", 1) times[name] = float(time) alltimes.append(times) return alltimes class BenchRunnerBaseTime(TimeRunner): def __init__(self, executable, logpath, options): TimeRunner.__init__(self, executable, logpath, options) self.numiter = options.basetime_numiter def run(self): self.write_benchheader("basetime") for name, opts, code in (('site', '', 'pass'), ('nosite', '-S', 'pass'), ('importos', '-S', "import os"), ('importdecimal', '-S', "import decimal"), ('importoptparse', '-S', "import optparse"), ): executable = py.path.local.sysfind(self.executable) p = self.tmpdir.join("launcher.py") p.write(code) if "launcher" in str(self.executable): opts = "" # any option will disable the launcher magic cmd = "%s %s %s" % (executable, opts, str(p)) times = self.timecommand(cmd) print >>self.logstream, "%s:%r" % (name, times) class BenchRunnerBenchTime(TimeRunner): def __init__(self, executable, logpath, options): TimeRunner.__init__(self, executable, logpath, options) self.numiter = options.basetime_numiter def run(self): self.write_benchheader("benchtime") for name, cmdpostfix, pattern in ( ('gcbench', '-c "import gcbench_runner; gcbench_runner.main()"', "T: "), ('pystone', '-c "import pystone; pystone.main(10000)"', PYSTONE_PATTERN), ('richards', '-c "import richards; richards.main(iterations=1)"', RICHARDS_PATTERN), ): executable = py.path.local.sysfind(self.executable) cmd = "%s %s " % (executable, cmdpostfix) times = self.timecommand(cmd, str(benchmarkdir), pattern) print >>self.logstream, "%s:%r" % (name, times) PYSTONE_CMD = 'from test import pystone;pystone.main(%s)' PYSTONE_PATTERN = 'This machine benchmarks at' RICHARDS_CMD = 'from richards import *;main(iterations=%d)' RICHARDS_PATTERN = 'Average time per iteration:' class BenchRunnerObjsize(BenchRunner): benchtype = 'objsizes' def __init__(self, executable, logpath, options): BenchRunner.__init__(self, executable, logpath, options) self.benchpath = benchmarkdir.join("sizes.py") assert self.benchpath.check() def makebench(self, name): arglist = str(self.options.numiter) source = py.code.Source(self.benchpath.read(), """ import gc def write(c): sys.stdout.write(c) sys.stdout.flush() def checkpoint(collect=False): if collect: gc.collect() write("c") sys.stdin.read(1) if __name__ == "__main__": import os, sys, gc pid = os.getpid() write(str(pid) + "\\n") checkpoint(collect=True) %s(%s) checkpoint(collect=True) write("F") sys.stdin.close() """ %(name, arglist)) p = self.tmpdir.join(self.benchpath.basename) p.write(source) return p def run(self): for name in self.getnames(): self.run_checkpointed(name) def run_checkpointed(self, name): benchpyfile = self.makebench(name) #self.log("created", benchpyfile) cmd = "%s -u %s" %(self.executable, benchpyfile) self.log("running %s(%s)" % (name, self.options.numiter)) stdout, stdin = os.popen2(cmd) pid = int(stdin.readline()) self.write_benchheader(name, self.options.numiter) rec = smaps.SmapsRecorder(pid, self.logstream) self.interact_with_child_checkpoints(rec, stdout, stdin) def interact_with_child_checkpoints(self, rec, stdout, stdin): def write(c): stdout.write(c) stdout.flush() while not stdin.closed: c = stdin.read(1) if c == "F": stdin.close() stdout.close() break rec.snapshot() stdout.write(".") stdout.flush() #sys.stdout.write(".") #sys.stdout.flush() class BenchRunnerAppProfiles(BenchRunner): ITER2 = 4 benchtype = 'appprofiles' def __init__(self, *args): BenchRunner.__init__(self, *args) self.benchpath = benchmarkdir.join("appprofiles.py") def run(self): for name in self.getnames(): self.run_once(name) def run_once(self, name): runner_file = self.makebench(name) #self.log("created", benchpyfile) cmd = "%s -u "% (self.executable, ) self.log("running %s(%s)" %(name, self.options.numiter)) # we want to avoid measuring the size impact of # compiler invocation, so we have to manually compile # the modules and hope # first compile the modules by importing a module that imports os.system(cmd + str(runner_file)) stdout, stdin = os.popen2(cmd + str(runner_file) + " run") pid = int(stdin.readline()) self.write_benchheader(name, self.options.numiter) rec = smaps.SmapsRecorder(pid, self.logstream, True, False) self.write_internal_header({"TS": str(time.time())}) rec.snapshot() stdout.write("!") stdout.flush() self.interact_with_child(rec, stdout, stdin) def makebench(self, name): arglist = (int(self.options.numiter), self.ITER2) runner_file = self.tmpdir.join("runner.py") runner_file.write(py.code.Source(""" import sys sys.path.insert(0, %r) from generatedbenchmark import init init() """ % (str(self.tmpdir), ))) source = py.code.Source(""" import sys, gc, os def write(c): sys.stdout.write(c) sys.stdout.flush() if len(sys.argv) > 1 and sys.argv[1] == 'run': pid = os.getpid() write(str(pid) + "\\n") sys.stdin.read(1) """, self.getbenchsource(), """ def init(): if len(sys.argv) > 1 and sys.argv[1] == 'run': %s %s sys.stdin.close() """ %(name, arglist)) p = self.tmpdir.join("generatedbenchmark.py") p.write(source) return runner_file def interact_with_child(self, rec, stdin, stdout): while not stdin.closed: try: ts = time.time() self.write_internal_header({"TS": str(ts)}) rec.snapshot() # if we yielded to the scheduler via sleep(), the process # under test would advance more than while we are running in # our sampling code. instead of that, we do busy waiting here # because some systems # this program is used on only provide 20 hz sampling rate # when doing no sleep at all. # also we do not adjust the waiting time to the wall clock # because this would give very different results based on # the system speed. a better solution would be cpu timers # or ptrace etc. for _ in xrange(2**14): pass except py.error.ENOENT: break rec.stream.flush() class BenchRunnerPauses(BenchRunner): benchtype = 'pauses' # this benchrunner uses a tracing hook # to send characters over a pipe to another process # only wall clock time can be tracked, the process # scheduling can therefore influence the measurements def __init__(self, *args): BenchRunner.__init__(self, *args) self.benchpath = benchmarkdir.join("appprofiles.py") self.last_t = None # XXX self.args = (1000, 3) def run(self): for name in self.getnames(): self.run_once(name) def write_footer(self): self.logstream.flush() def measure(self): if self.last_t is not None: t = time.time() diff = t - self.last_t self.logstream.write(str(diff) + "\n") self.last_t = time.time() def run_once(self, name): self.write_benchheader(name, self.args) from tracer import trace_in_another_process trace_in_another_process(self.tmpdir.join(self.benchpath.basename), self.getbenchsource(), name, self.measure, self.executable, self.args) self.write_footer() # # ================ reading a benchmark log file ======================= # def parseheader(stream_iter): kw = {} for lineno, line in stream_iter: if not line.strip(): return kw assert line.startswith("#"), line key, value = map(str.strip, line[1:].split("=")) kw[key] = value def parse_result(stream, kw): benchtype = kw.pop('benchtype') chosen_cls = benchtype2class[benchtype] return chosen_cls.parse(stream, kw) class ResultSet(object): def __init__(self, results=None): if results is None: results = [] self.results = results def __nonzero__(self): return bool(self.results) def getname2results(self): name2results = {} for result in self.results: l = name2results.setdefault(result.benchname, []) l.append(result) return name2results.items() def getexecutables(self, basename_only=False): names = [result.executable for result in self.results] if basename_only: names = [name.rsplit(os.path.sep, 1)[1] for name in names] return names def filter(self, benchtype): l = [] for result in self.results: if benchtype == None or result.benchtype == benchtype: l.append(result) return ResultSet(l) def parse(self, logpath): f = logpath.open() self.results.extend(self.yield_results(f)) f.close() def yield_results(self, stream): stream_iter = enumerate(stream) for lineno, line in stream_iter: line = line.rstrip() if line != BenchRunner.SEPBENCH: print "ignoring %d: %s" % (lineno, line) else: break while 1: kw = parseheader(stream_iter) if kw is None: break yield parse_result(stream_iter, kw) class Result(object): @classmethod def parse(cls, lnstream, kw): snapshots = [] mappings = [] headerkw = {} for lineno, line in lnstream: line = line.rstrip() if line == smaps.SmapsRecorder.SEPSNAPSHOT: snapshots.append(Snapshot(mappings, headerkw)) mappings = [] headerkw = {} elif line == BenchRunner.SEPBENCH: break else: if line.startswith(BenchRunner.HEADERSEP): headerkw.update(parseheader(lnstream)) continue mappings.append(smaps.Mapping(line)) continue return cls(snapshots, **kw) @property def executable_short(self): return self.executable.rsplit(os.path.sep)[-1].replace("-c-", "-").replace("-maemo", "") class CommonResult(Result): def __init__(self, snapshots, executable, benchpath, benchname, benchargs): assert snapshots self.snapshots = snapshots self.executable = executable self.benchpath = benchpath self.benchname = benchname self.benchargs = benchargs class ObjsizeResult(CommonResult): benchtype = "objsizes" def max(self, attrname): maxvalue = 0 for snap in self.snapshots: maxvalue = max(maxvalue, getattr(snap, attrname)) return maxvalue def _verify_integrity(self): for snap in self.snapshots: for mapping in snap.mappings: clean = mapping.shared_clean + mapping.private_clean dirty = mapping.private_dirty + mapping.shared_dirty assert mapping.rss == dirty + clean class AppprofileResult(CommonResult): benchtype = "appprofiles" def __init__(self, snapshots, *args, **kwargs): CommonResult.__init__(self, snapshots, *args, **kwargs) avg = lambda x: sum(x) / float(len(snapshots)) heap_values = [ss.heap_and_data(self) for ss in snapshots] self.min = min(heap_values) self.max = max(heap_values) # XXX this way we are not integrating over time so we have skew again self.avg = avg(heap_values) code_values = [ss.filter(group=self.executable, kind=Mappings.CODE).rss for ss in snapshots] dirty_data_values = [ss.filter(group=self.executable, kind=Mappings.DATA).dirty for ss in snapshots] data_values = [ss.filter(group=self.executable, kind=Mappings.DATA).rss for ss in snapshots] self.max_code = max(code_values) self.min_code = min(code_values) self.avg_code = avg(code_values) self.max_dirtied_data = max(dirty_data_values) self.min_dirtied_data = min(dirty_data_values) self.avg_dirtied_data = avg(dirty_data_values) self.min_data = min(data_values) self.avg_data = avg(data_values) self.max_data = max(data_values) class BasesizeResult(Result): benchtype = 'basesize' def __init__(self, snapshots, executable): self.snapshot = snapshots[0] assert len(snapshots) == 1 self.executable = executable class TimeResult(Result): def __init__(self, timings, executable): self.timings = timings self.executable = executable self.mintimings = [] for name, timing in timings: if timing: self.mintimings.append((name, min(timing, key=lambda x: x['real']))) @classmethod def parse(cls, lnstream, kw): timings = [] for lineno, line in lnstream: if line.strip() == BenchRunner.SEPBENCH: break name, data = line.split(":", 1) times = eval(data) timings.append((name, times)) return cls(timings, **kw) class BasetimeResult(TimeResult): benchtype = 'basetime' def __init__(self, timings, executable): TimeResult.__init__(self, timings, executable) class BenchTimeResult(TimeResult): benchtype = "benchtime" class PausesResult(Result): benchtype = 'pauses' def __init__(self, lst, **kw): for k, v in kw.items(): setattr(self, k, v) self.lst = lst @classmethod def parse(cls, lnstream, kw): lst = [] for lineno, line in lnstream: if line.strip() == BenchRunner.SEPBENCH: break lst.append(float(line)) return cls(lst, **kw) benchtype2class = {} def _update_benchtyp2class(): for cls in globals().values(): if Result in getattr(cls, '__mro__', []) and getattr(cls, 'benchtype', None): benchtype2class[cls.benchtype] = cls _update_benchtyp2class() class Mappings(object): HEAP, CODE, DATA = object(), object(), object() def __init__(self, mappings): self.mappings = mappings for name in smaps.Mapping._attrnames: setattr(self, name, sum([getattr(x, name) for x in mappings])) self.private = self.private_dirty + self.private_clean self.shared = self.shared_dirty + self.shared_clean self.dirty = self.private_dirty + self.shared_dirty self.clean = self.private_clean + self.shared_clean def filter(self, group=None, kind=None, inv=False): new_mappings = [] for mapping in self.mappings: matches = True if group is not None: if group is self.HEAP: if not (mapping.filename == "[heap]" or not mapping.filename): matches = False elif not group in mapping.filename: matches = False if kind is not None: if kind is self.CODE and mapping.mode != 'r-xp': matches = False # XXX why is the data mapping sometimes executable? if kind is self.DATA and mapping.mode not in ('rw-p', 'rwxp'): matches = False if matches != bool(inv): new_mappings.append(mapping) return Mappings(new_mappings) def memusage(self): return "private: %d, shared: %d" %(self.private, self.shared) class SimpleSnapshot(object): def __init__(self, private, timestamp): self.private = private self.timestamp = timestamp class Snapshot(Mappings): def __init__(self, mappings, headerkw={}): assert mappings self.header = headerkw Mappings.__init__(self, mappings) if "TS" in headerkw: self.timestamp = float(headerkw["TS"]) def heap_private(self): return self.filter(group=self.HEAP).private def heap_and_data(self, result): return self.filter(group=self.HEAP).private_dirty + self.filter(group=result.executable, kind=self.DATA).private_dirty # # ============================================================================== # Option Handling parser = optparse.OptionParser(usage=__doc__) parser.add_option("-e", "--executable", action="store", dest="executable", default="python2.5", help="Python executable to use for recording benchmarks") parser.add_option("-l", "--benchlog", action="store", dest="benchlog", default="bench.log", help="logfile for recording benchmark measurements") parser.add_option("-a", "--append", action="store_true", dest="append", default=False, help="append to logfile") parser.add_option("-n", "--numiter", action="store", dest="numiter", default=1000, help="number of iterations") parser.add_option("--basetime-numiter", action="store", dest="basetime_numiter", default=10, help="number of iterations for base startup time") def getbenchlog(options): benchlog = options.benchlog if benchlog is None: benchlog = "bench.log" benchlog = py.path.local(benchlog) if not options.append and benchlog.check(): benchlog.remove() return benchlog def getexecutables(options): l = [] for executable in options.executable.split(","): if not executable: continue p = py.path.local(executable) if not p.check(): p = py.path.local.sysfind(executable) if not p or not p.check(): raise SystemExit("could not find %r"% (executable)) l.append(executable) return l def getrunnerclass(benchtype): if benchtype == "objsizes": return BenchRunnerObjsize elif benchtype == "basesize": return BenchRunnerBaseSize elif benchtype == "benchtime": return BenchRunnerBenchTime elif benchtype == "basetime": return BenchRunnerBaseTime elif benchtype == "appprofiles": return BenchRunnerAppProfiles elif benchtype == 'pauses': return BenchRunnerPauses else: raise NotImplementedError("Benchmark type: %s" % (benchtype,)) if __name__ == '__main__': (options, args) = parser.parse_args() options.basetime_numiter = int(options.basetime_numiter) # how to do this above? benchlog = getbenchlog(options) if not args: args = ("objsizes", "basesize", "basetime", "appprofiles", "pauses", "benchtime") for executable in getexecutables(options): for benchtype in args: Runner = getrunnerclass(benchtype) runner = Runner(executable, benchlog, options) runner.run() print "bench results append to -->>>", benchlog