fix: modules were only pre-imported when verbose was 2

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

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)
+

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)
@@ -208,11 +217,6 @@ def main(argv=sys.argv):
             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__':
     main()

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',
         ]
     }
 )