Update tracer to give more information

scripts/graph_tracer.py

@@ -1,5 +1,16 @@
 import fileinput
 import pydot
+import sys
+import itertools
+import json
+
+
+def pairwise(iterable):
+    "s -> (s0,s1), (s1,s2), (s2, s3), ..."
+    a, b = itertools.tee(iterable)
+    next(b, None)
+    return itertools.izip(a, b)
+
 
 nodes = {}
 edges = set()
@@ -7,38 +18,51 @@ edges = set()
 graph = pydot.Dot(graph_name="call_graph", graph_type="digraph")
 
 names = {}
-times = {}
-deferreds = {}
+starts = {}
+ends = {}
+deferreds = set()
+deferreds_map = {}
 deferred_edges = set()
 
 root_id = None
 
 for line in fileinput.input():
+    line = line.strip()
     try:
         if " calls " in line:
             start, end = line.split(" calls ")
             start, end = start.strip(), end.strip()
             edges.add((start, end))
-            print start, end
+            # print start, end
         if " named " in line:
             node_id, name = line.split(" named ")
             names[node_id.strip()] = name.strip()
 
-            if name.strip() == "Deferred synapse.rest.client.v1.room.RoomSendEventRestServlet.on_PUT":
+            if name.strip() == "synapse.rest.client.v1.room.RoomSendEventRestServlet.on_PUT":
                 root_id = node_id
         if " in " in line:
             node_id, d = line.split(" in ")
-            deferreds[node_id.strip()] = d.strip()
-        if " time " in line:
-            node_id, ms = line.split(" time ")
-            times[node_id.strip()] = int(ms.strip())
+            deferreds_map[node_id.strip()] = d.strip()
+        if " is deferred" in line:
+            node_id, _ = line.split(" is deferred")
+            deferreds.add(node_id)
+        if " start " in line:
+            node_id, ms = line.split(" start ")
+            starts[node_id.strip()] = int(ms.strip())
+        if " end " in line:
+            node_id, ms = line.split(" end ")
+            ends[node_id.strip()] = int(ms.strip())
         if " waits on " in line:
             start, end = line.split(" waits on ")
             start, end = start.strip(), end.strip()
             deferred_edges.add((start, end))
-            print start, end
+            # print start, end
     except Exception as e:
-        print "failed %s to parse '%s'" % (e.message, line)
+        sys.stderr.write("failed %s to parse '%s'\n" % (e.message, line))
+
+if not root_id:
+    sys.stderr.write("Could not find root")
+    sys.exit(1)
 
 
 # deferreds_root = set(deferreds.values())
@@ -59,8 +83,8 @@ for line in fileinput.input():
 #     tree = deferred_tree.setdefault(d, {})
 #     populate(d, tree)
 
-print deferred_edges
-print root_id
+# print deferred_edges
+# print root_id
 
 def is_in_deferred(d):
     while True:
@@ -74,16 +98,77 @@ def is_in_deferred(d):
         else:
             return False
 
+
+def walk_graph(d):
+    res = [d]
+    while d != root_id:
+        for start, end in edges:
+            if d == end:
+                d = start
+                res.append(d)
+                break
+        else:
+            return res
+    return res
+
+
+def make_tree_el(node_id):
+    return {
+        "id": node_id,
+        "name": names[node_id],
+        "children": [],
+        "start": starts[node_id],
+        "end": ends[node_id],
+        "size": ends[node_id] - starts[node_id],
+    }
+
+tree = make_tree_el(root_id)
+
+tree_index = {
+    root_id: tree,
+}
+
+
+viz_out = {
+    "nodes": [],
+    "edges": [],
+}
+
 for node_id, name in names.items():
     # if times.get(node_id, 100) < 5:
     #     continue
 
+    walk = walk_graph(node_id)
+    # print walk
+    if root_id not in walk:
+        continue
+
     if node_id in deferreds:
-        if not is_in_deferred(deferreds[node_id]):
-            continue
-    else:
         if not is_in_deferred(node_id):
             continue
+    elif node_id in deferreds_map:
+        if not is_in_deferred(deferreds_map[node_id]):
+            continue
+
+    walk_names = [
+        names[w].split("synapse.", 1)[1] for w in walk
+    ]
+
+    for child, parent in reversed(list(pairwise(walk))):
+        if parent in tree_index and child not in tree_index:
+            el = make_tree_el(child)
+            tree_index[parent]["children"].append(el)
+            tree_index[child] = el
+
+    # print "-".join(reversed(["end"] + walk_names)) + ", " + str(ends[node_id] - starts[node_id])
+    # print "%d,%s,%s,%s" % (len(walk), walk_names[0], starts[node_id], ends[node_id])
+
+    viz_out["nodes"].append({
+        "id": node_id,
+        "label": names[node_id].split("synapse.", 1)[1],
+        "value": ends[node_id] - starts[node_id],
+        "level": len(walk),
+    })
 
     node = pydot.Node(node_id, label=name)
 
@@ -98,18 +183,30 @@ for node_id, name in names.items():
 
     # print node_id
 
+# for el in tree_index.values():
+#     el["children"].sort(key=lambda e: e["start"])
+#
+# print json.dumps(tree)
+
 for parent, child in edges:
     if child not in nodes:
-        print child, "not a node"
+        # sys.stderr.write(child + " not a node\n")
         continue
 
     if parent not in nodes:
-        print parent, "not a node"
+        # sys.stderr.write(parent + " not a node\n")
         continue
 
+    viz_out["edges"].append({
+        "from": parent,
+        "to": child,
+        "value": ends[child] - starts[child],
+    })
+
     edge = pydot.Edge(nodes[parent], nodes[child])
     graph.add_edge(edge)
 
+print json.dumps(viz_out)
 
 file_prefix = "call_graph_out"
 graph.write('%s.dot' % file_prefix, format='raw', prog='dot')

synapse/util/traceutil.py

@@ -29,6 +29,7 @@ class Tracer(object):
 
         self.next_id = 1
 
+        self.deferred_frames = {}
         self.deferred_to_current_frames = {}
 
     def process(self, frame, event, arg):
@@ -44,11 +45,16 @@ class Tracer(object):
             trace_id = self.get_next_id()
             deferred.syn_trace_defer_id = trace_id
             logger.info(
-                "%s named Deferred %s",
+                "%s named %s",
                 trace_id,
                 self.get_name_for_frame(generator.gi_frame)
             )
 
+            logger.info(
+                "%s is deferred",
+                trace_id,
+            )
+
             logger.info("%s start %d", trace_id, int(time.time() * 1000))
 
             def do(res):