From 2e3b74c06bea26f64fc3a0a26b6c5f962691b451 Mon Sep 17 00:00:00 2001 From: "Maarten A. Breddels" Date: Thu, 17 Dec 2020 08:10:59 +0100 Subject: [PATCH] fix: modules were only pre-imported when verbose was 2 --- per4m/__main__.py | 3 ++ per4m/giltracer.py | 2 +- per4m/offgil.py | 96 +++++++++++++++++++++++++++++++++++++++++++++ per4m/perf2trace.py | 34 +++++++++------- per4m/record.py | 2 +- setup.py | 1 + 6 files changed, 121 insertions(+), 17 deletions(-) create mode 100644 per4m/offgil.py diff --git a/per4m/__main__.py b/per4m/__main__.py index 7ea0d98..94d6b6d 100644 --- a/per4m/__main__.py +++ b/per4m/__main__.py @@ -8,6 +8,7 @@ optional arguments: positional arguments: giltracer Run VizTracer and perf, and merge the result to see where the GIL is active. + offgil Take stacktraces from VizTracer, and inject them in perf script output and print out stack traces with weights for stackcollapse.pl record Run VizTracer and perf simultaneously. See also man perf record. script Take stacktraces from VizTracer, and inject them in perf script output. perf2trace Convert perf.data to TraceEvent JSON data. @@ -27,6 +28,8 @@ def main(args=sys.argv): main([os.path.basename(args[0]) + " " + args[1]] + args[2:]) elif len(args) > 1 and args[1] == "giltracer": from .giltracer import main + elif len(args) > 1 and args[1] == "offgil": + from .offgil import main main([os.path.basename(args[0]) + " " + args[1]] + args[2:]) elif len(args) > 1 and args[1] == "record": from .record import main diff --git a/per4m/giltracer.py b/per4m/giltracer.py index 16a5a8d..6df9c60 100644 --- a/per4m/giltracer.py +++ b/per4m/giltracer.py @@ -48,7 +48,7 @@ def main(argv=sys.argv): for module in args.import_.split(','): if verbose >= 2: print(f'importing {module}') - __import__(module) + __import__(module) with GilTracer(verbose=verbose) as gt: with viztracer.VizTracer(output_file="viztracer.json", verbose=verbose): diff --git a/per4m/offgil.py b/per4m/offgil.py new file mode 100644 index 0000000..5d20d90 --- /dev/null +++ b/per4m/offgil.py @@ -0,0 +1,96 @@ +import argparse +import json +import shlex +import subprocess +import sys + +from viztracer.prog_snapshot import ProgSnapshot + + +from .perfutils import read_events, parse_header +from .script import stacktrace_inject, print_stderr +from .perf2trace import perf2trace + + +usage = """ + +Take stacktraces from VizTracer, and inject them in perf script output and print out stack traces with weights for stackcollapse.pl +(from https://github.com/brendangregg/FlameGraph ) + +Usage: + +$ giltracer -m per4m.example3 +$ offgil | ~/github/FlameGraph/stackcollapse.pl | ~/github/FlameGraph/flamegraph.pl --countname=us --title="Off-GIL Time Flame Graph" --colors=python > offgil.svg +""" + + +def main(argv=sys.argv): + parser = argparse.ArgumentParser(argv[0], + formatter_class=argparse.RawDescriptionHelpFormatter, + usage=usage) + parser.add_argument('--verbose', '-v', action='count', default=0) # by default quiet, since we write to stdout + parser.add_argument('--quiet', '-q', action='count', default=0) + parser.add_argument('--state', help='State to match (default: %(default)s)', default="S(GIL)") + parser.add_argument('--strip-take-gil', dest="strip_take_gil", help="Remove everything from the stack above take_gil (default: %(default)s)", default=True, action='store_true') + parser.add_argument('--no-strip-take-gil', dest="strip_take_gil", action='store_false') + parser.add_argument('--keep-cpython-evals', help="keep CPython evaluation stacktraces (instead of replacing) (default: %(default)s)", default=False, action='store_true') + parser.add_argument('--no-keep-cpython-evals', dest="keep_cpython_evals", action='store_false') + parser.add_argument('--allow-mismatch', help="Keep going even when we cannot match the C and Python stacktrace (default: %(default)s)", default=False, action='store_true') + parser.add_argument('--no-allow-mismatch', dest="allow_mismatch", action='store_false') + parser.add_argument('--pedantic', help="If false, accept known stack mismatch issues (default: %(default)s)", default=False, action='store_true') + parser.add_argument('--no-pedantic', dest="pedantic", action='store_false') + parser.add_argument('--input', '-i', help="VizTracer input (default %(default)s)", default="viztracer.json") + parser.add_argument('--output', '-o', dest="output", default=None, help="Output filename (default %(default)s)") + + + args = parser.parse_args(argv[1:]) + verbose = args.verbose - args.quiet + + perf_script_args = ['--no-inline'] + perf_script_args = ' '.join(perf_script_args) + cmd = f"perf script {perf_script_args}" + if verbose >= 2: + print(f"Running: {cmd}") + perf_args = shlex.split(cmd) + perf = subprocess.Popen(perf_args, shell=False, stdout=subprocess.PIPE, stderr=subprocess.PIPE, text=True) #, stdin=subprocess.PIPE) + + if args.output is None: + output = sys.stdout + else: + output = open(args.output, "w") + + if verbose >= 1: + print_stderr("Loading snapshot") + with open(args.input, "r") as f: + json_data = f.read() + snap = ProgSnapshot(json_data) + # find all pids (or tids) + pids = list(snap.func_trees) + for pid in pids.copy(): + pids.extend(list(snap.func_trees[pid])) + t0 = min(event['ts'] for event in json.loads(json_data)['traceEvents']) + + for header, stacktrace, event in perf2trace(perf.stdout, verbose): + if event['name'] == args.state: + values, _, _ = parse_header(header) + time = values['time'] - t0 + triggerpid = event['tid'] + if triggerpid in pids: + try: + stacktrace = stacktrace_inject(stacktrace, snap, triggerpid, time, keep_cpython_evals=args.keep_cpython_evals, allow_mismatch=args.allow_mismatch, pedantic=args.pedantic) + if args.strip_take_gil: + take_gil_index = None + for i, call in enumerate(stacktrace): + if 'take_gil' in call: + take_gil_index = i + if take_gil_index is not None: # shouldn't it be always there? + stacktrace = stacktrace[take_gil_index:] + for call in stacktrace: + ptr, signature = call.split(' ', 1) + print(signature, file=output) + except: + print_stderr(f"Error for event: {header}") + raise + print(int(event['dur'])) + print(file=output) + diff --git a/per4m/perf2trace.py b/per4m/perf2trace.py index e3d2abb..6d8dfee 100644 --- a/per4m/perf2trace.py +++ b/per4m/perf2trace.py @@ -57,9 +57,20 @@ def main(argv=sys.argv): args = parser.parse_args(argv[1:]) + verbose = args.verbose - args.quiet + store_runing = args.running + store_sleeping = args.sleeping trace_events = [] + for header, tb, event in perf2trace(sys.stdin, verbose=verbose, store_runing=store_runing, store_sleeping=store_sleeping, all_tracepoints=args.all_tracepoints): + trace_events.append(event) + with open(args.output, 'w') as f: + json.dump({'traceEvents': trace_events}, f) + if verbose >= 1: + print(f"Wrote to {args.output}") + +def perf2trace(input, verbose=1, store_runing=False, store_sleeping=True, all_tracepoints=False): # useful for debugging, to have the pids a name pid_names = {} # pid_names = {872068: "main", 872070: "t1", 872071: "t2"} @@ -67,15 +78,12 @@ def main(argv=sys.argv): last_run_time = {} last_sleep_time = {} last_sleep_stacktrace = {} - verbose = args.verbose - args.quiet time_first = None - store_runing = args.running - store_sleeping = args.sleeping parent_pid = {} # maps pid/tid to the parent count = None - for header, stacktrace in read_events(sys.stdin): + for header, stacktrace in read_events(input): try: - if args.verbose >= 3: + if verbose >= 3: print(header) pid = None parts = header.split() @@ -94,8 +102,8 @@ def main(argv=sys.argv): def log(*args, time=time/1e6): offset = time - time_first/1e6 print(f"{time:13.6f}[+{offset:5.4f}]", *args) - if args.all_tracepoints and tracepoint: - trace_events.append({'name': event, 'pid': parent_pid.get(pid, pid), 'tid': triggerpid, 'ts': time, 'ph': 'i', 's': 'g'}) + if all_tracepoints and tracepoint: + yield header, stacktrace, {'name': event, 'pid': parent_pid.get(pid, pid), 'tid': triggerpid, 'ts': time, 'ph': 'i', 's': 'g'} first_line = False gil_event = None if event == "sched:sched_switch": @@ -126,7 +134,7 @@ def main(argv=sys.argv): log(f'{name} will switch to state={prev_state}, ran for {dur}') if store_runing: event = {"pid": parent_pid.get(pid, pid), "tid": pid, "ts": last_run_time[pid], "dur": dur, "name": 'R', "ph": "X", "cat": "process state"} - trace_events.append(event) + yield header, stacktrace, event last_sleep_time[pid] = time last_sleep_stacktrace[pid] = stacktrace @@ -168,7 +176,8 @@ def main(argv=sys.argv): name = 'S' cname = 'bad' event = {"pid": parent_pid.get(pid, pid), "tid": pid, "ts": last_sleep_time[pid], "dur": duration, "name": name, "ph": "X", "cat": "process state", 'cname': cname} - trace_events.append(event) + # A bit ugly, but here we lie about the stacktrace, we actually yield the one that caused us to sleep (for offgil.py) + yield header, last_sleep_stacktrace[pid], event last_run_time[pid] = time del last_sleep_time[pid] elif event == "sched:sched_process_exec": @@ -197,7 +206,7 @@ def main(argv=sys.argv): parent_pid[child_pid] = pid elif not tracepoint: event = {"pid": 'counters', "ts": time, "name": event, "ph": "C", "args": {event: count}} - trace_events.append(event) + yield header, stacktrace, event else: if verbose >= 2: print("SKIP", header) @@ -207,11 +216,6 @@ def main(argv=sys.argv): except: print("error on line", header, other) raise - - with open(args.output, 'w') as f: - json.dump({'traceEvents': trace_events}, f) - if verbose >= 1: - print(f"Wrote to {args.output}") if __name__ == '__main__': diff --git a/per4m/record.py b/per4m/record.py index c22da47..35705ff 100644 --- a/per4m/record.py +++ b/per4m/record.py @@ -120,7 +120,7 @@ def main(argv=sys.argv): for module in args.import_.split(','): if verbose >= 2: print(f'importing {module}') - __import__(module) + __import__(module) viztracer_path = args.output_viztracer ctx = contextlib.redirect_stdout(None) if verbose == 0 else empty_context() diff --git a/setup.py b/setup.py index 9264ad6..cb77cf8 100644 --- a/setup.py +++ b/setup.py @@ -21,6 +21,7 @@ setup( 'giltracer = per4m.giltracer:main', 'perf-pyrecord = per4m.record:main', 'perf-pyscript = per4m.script:main', + 'offgil = per4m.offgil:main', ] } )