tools/trace: Add trace analysis tools

Change-Id: I8edf7ab6e227bd374009da34df008a9ccf418825

tools/trace/ice-transport/stats

@@ -0,0 +1,131 @@
+#!/usr/bin/env python3
+
+import argparse
+
+import bt2
+
+def main(args):
+
+    path = args.path[0]
+
+    if args.tid < 0:
+        vtids = {
+            msg.event["vtid"]
+            for msg in bt2.TraceCollectionMessageIterator(path)
+            if type(msg) is bt2._EventMessageConst
+        }
+    else:
+        vtids = [args.tid]
+
+    for tid in vtids:
+        analyze_trace(path, tid)
+
+def analyze_trace(path, tid):
+
+    send_avg  = 0
+    recv_avg  = 0
+    send_N    = 0
+    recv_N    = 0
+    send_hist = []
+    recv_hist = []
+
+    prefix = "jami:ice_transport_"
+
+    def pkt_hist(hist, size):
+
+        diff = size - len(hist)
+
+        if diff >= 0:
+            hist += [0] * (diff + 1)
+
+        hist[size] += 1
+
+    for msg in bt2.TraceCollectionMessageIterator(path):
+
+        if type(msg) is bt2._EventMessageConst:
+
+            name = msg.event.name
+
+            if msg.event["vtid"] != tid:
+                continue
+
+            if not name.startswith(prefix):
+                continue
+
+            name = name[len(prefix):]
+
+            if name == "send":
+
+                pkt_len = msg.event["packet_length"]
+
+                pkt_hist(send_hist, pkt_len)
+
+                send_avg += pkt_len
+                send_N   += 1
+
+            elif name == "recv":
+
+                pkt_len = msg.event["packet_length"]
+
+                pkt_hist(recv_hist, pkt_len)
+
+                recv_avg += pkt_len
+                recv_N   += 1
+
+    if send_N != 0:
+        send_avg /= send_N
+
+    if recv_N != 0:
+        recv_avg /= recv_N
+
+    if send_hist or recv_hist:
+        print(f"Thread: {tid}")
+        print("{:^20s}\t{:^20s}\t{:^20s}".format("Direction", "Count", "Average size (bytes)"))
+        print("{:^20s}\t{:^20d}\t{:^20d}".format("Send", send_N, int(send_avg)))
+        print("{:^20s}\t{:^20d}\t{:^20d}".format("Recv", recv_N, int(recv_avg)))
+        print("")
+
+        if send_hist:
+            print_hist("Send", send_hist, args.log_scale)
+
+        if recv_hist:
+            print_hist("Recv", recv_hist, args.log_scale)
+
+        print("")
+
+
+def print_hist(name, bins, log_scale=False):
+
+    total_count = sum(bins)
+
+    if log_scale:
+        next_hi = lambda x: 2 * x
+    else:
+        next_hi = lambda x: x + 1
+
+    lo = 0
+    hi = 1
+
+    print('=' * 80)
+    print("{:^22s}|{:^10s}|{:^45s}|".format(name, "count", "distribution"))
+    print('-' * 80)
+
+    while lo < len(bins):
+        count = sum(bins[lo:hi])
+        print("{:>9d} -> {:<9d}|{:^10d}|{:45s}|".format(lo, hi, count, "*" * int(45 * count / total_count)))
+        lo = hi
+        hi = next_hi(hi)
+    print('=' * 80)
+
+if __name__ == "__main__":
+
+    parser = argparse.ArgumentParser(description="Show ICE transport statistics.")
+
+    parser.add_argument("path", metavar="TRACE", type=str, nargs=1)
+    parser.add_argument("tid", metavar="TID", type=int, nargs='?', default=-1)
+    parser.add_argument("--log-scale", action="store_true")
+    parser.add_argument("--scale", type=int, default=1)
+
+    args = parser.parse_args()
+
+    main(args)

tools/trace/timeline/executor

@@ -0,0 +1,90 @@
+#!/usr/bin/env python3
+
+import argparse
+from datetime import datetime
+
+import bt2
+
+class Thread:
+
+    def __init__(self):
+        self.tasks     = {}
+        self.executors = {}
+
+class Task:
+
+    def __init__(self, beg, end):
+        self.source = "{}:{}".format(beg.event["source_filename"], beg.event["source_line"])
+        self.sched  = datetime.utcfromtimestamp(beg.default_clock_snapshot.ns_from_origin // 1E9).strftime("%X")
+        self.elapse = (end.default_clock_snapshot.ns_from_origin -
+                       beg.default_clock_snapshot.ns_from_origin) / 1E3
+
+def print_timeline(name, tasks):
+    print(f"\tExecutor: {name}")
+    print("\t\t{:<12s}{:<15}source".format("scheduled", "duration (µs)"))
+    for task in tasks:
+        print("\t\t{:<12s}{:<15.2f}{}".format(task.sched, task.elapse, task.source))
+    print("")
+
+def main(args):
+
+    filter_tid = args.tid
+    threads    = {}
+    prefix     = "jami:scheduled_executor_"
+
+    for msg in bt2.TraceCollectionMessageIterator(args.path[0]):
+
+        if type(msg) is bt2._EventMessageConst:
+
+            name = msg.event.name
+
+            if filter_tid > 0 and msg.event["vtid"] != filter_tid:
+                continue
+
+            tid = msg.event["vtid"]
+
+            if tid not in threads:
+                threads[tid] = Thread()
+
+            thread = threads[tid]
+
+            tasks = thread.tasks
+
+            if not name.startswith(prefix):
+                continue
+
+            name = name[len(prefix):]
+
+            if name == "task_begin":
+                tasks[msg.event["cookie"]] = msg
+
+            elif name == "task_end":
+
+                executors = thread.executors
+
+                begin    = tasks[msg.event["cookie"]]
+                end      = msg
+                task     = Task(begin, end)
+                executor = begin.event["executor"]
+
+                if executor not in executors:
+                    executors[executor] = [task]
+                else:
+                    executors[executor].append(task)
+
+    for tid, thread in threads.items():
+        if thread.executors:
+            print(f"Thread: {tid}")
+            for executor, tasks in thread.executors.items():
+                print_timeline(executor, tasks)
+
+if __name__ == "__main__":
+
+    parser = argparse.ArgumentParser(description="Show scheduled executors timeline.")
+
+    parser.add_argument("path", metavar="TRACE", type=str, nargs=1)
+    parser.add_argument("tid", metavar="TID", type=int, nargs='?', default=-1)
+
+    args = parser.parse_args()
+
+    main(args)

tools/trace/timeline/signals

@@ -0,0 +1,113 @@
+#!/usr/bin/env python3
+
+import argparse
+from datetime import datetime
+
+import bt2
+
+class Thread:
+
+    def __init__(self):
+        self.signals  = []
+        self.pendings = []
+
+class Signal:
+
+    def __init__(self, msg, indent):
+        self.indent    = indent
+        self.beg       = msg
+        self.signals   = []
+        self.callbacks = []
+        self.pendings  = []
+        self.elapse    = -1
+
+    def end(self, end):
+        self.elapse = (end.default_clock_snapshot.ns_from_origin -
+                       self.beg.default_clock_snapshot.ns_from_origin) / 1E3
+        return self
+
+    def __str__(self):
+        return "{:.2f}us: {}".format(self.elapse, self.beg.event["signal_type"])
+
+class Callback():
+
+    def __init__(self, begin):
+        self.source = "{}:{}".format(begin.event["source_filename"],
+                                     begin.event["source_line"])
+        self.beg    = begin
+        self.elapse = -1
+        self.name   = ""
+
+    def end(self, end):
+        self.elapse = (end.default_clock_snapshot.ns_from_origin -
+                       self.beg.default_clock_snapshot.ns_from_origin) / 1E3
+        return self
+
+def print_timeline(thread):
+    for s in thread.signals:
+        prefix = "\t" * s.indent
+        print(f"{prefix}{s}")
+        print("{}\t{:<30s}{:<15}".format(prefix, "callback", "duration (%)"))
+        for cb in s.callbacks:
+            print("{}\t{:<30s}{:<.2f}".format(prefix,
+                                              cb.source,
+                                              100 *cb.elapse / s.elapse))
+        print("")
+
+def main(args):
+
+    filter_tid = args.tid
+    threads   = {}
+    prefix      = "jami:emit_signal"
+
+    for msg in bt2.TraceCollectionMessageIterator(args.path[0]):
+
+        if type(msg) is bt2._EventMessageConst:
+
+            name = msg.event.name
+
+            if not name.startswith(prefix):
+                continue
+
+            if filter_tid > 0 and msg.event["vtid"] != filter_tid:
+                continue
+
+            tid = msg.event["vtid"]
+
+            if tid not in threads:
+                threads[tid] = Thread()
+
+            thread = threads[tid]
+
+            pendings = thread.pendings
+
+            name = name[len(prefix):]
+
+            if name == "":
+                pendings.append(Signal(msg, len(pendings) + 1))
+
+            elif name == "_end":
+                thread.signals.append(pendings.pop().end(msg))
+
+            elif name == "_begin_callback":
+                signal = pendings[-1]
+                signal.pendings.append(Callback(msg))
+
+            elif name == "_end_callback":
+                signal = pendings[-1]
+                signal.callbacks.append(signal.pendings.pop().end(msg))
+
+    for tid, thread in threads.items():
+        print(f"Thread: {tid}")
+        print_timeline(thread)
+
+if __name__ == "__main__":
+
+    parser = argparse.ArgumentParser(description="Show signals timeline.")
+
+    parser.add_argument("path", metavar="TRACE", type=str, nargs=1)
+    parser.add_argument("tid", metavar="TID", type=int, nargs='?', default=-1)
+
+    args = parser.parse_args()
+
+    main(args)

tools/trace/trace-jami

@@ -0,0 +1,28 @@
+#!/bin/sh
+
+epilogue() {
+    lttng stop
+    lttng destroy
+    exit 0
+}
+
+trap epilogue SIGINT
+
+lttng create jami
+lttng enable-event --userspace 'jami:*'
+lttng add-context --userspace --type=vtid
+
+for arg in "$@"; do
+    case "$arg" in
+        "--") break ;;
+        *) lttng add-context --userspace --type="$1" ;;
+    esac
+    shift
+done
+shift
+
+lttng start
+
+$@
+
+epilogue