Convert 'perf script' output to about:tracing json.

tools/convert_perf_script_to_tracing_json.py

Index: tools/convert_perf_script_to_tracing_json.py
diff --git a/tools/convert_perf_script_to_tracing_json.py b/tools/convert_perf_script_to_tracing_json.py
new file mode 100755
index 0000000000000000000000000000000000000000..3bb468008d830e816f025baa8b3f524dc1d1cd21
--- /dev/null
+++ b/tools/convert_perf_script_to_tracing_json.py
@@ -0,0 +1,172 @@
+#!/usr/bin/python
+# Copyright (c) 2012 The Chromium Authors. All rights reserved.
+# Use of this source code is governed by a BSD-style license that can be
+# found in the LICENSE file.
+
+import json
+import re
+import sys
+
+"""Converts the output of "perf script" into json for about:tracing.
+
+Usage: perf script | convert_perf_script_to_tracing_json.py > trace.json
+"""
+
+# FIXME: Signal to the traceviewer that this is a CPU profile so it shows
+# samples instead of ms as the units.

[eseidel, 2014/04/05 00:03:13]

The samples themselves can sorta represent 0.1ms or whatever the sampling
frequency is.

[ojan, 2014/04/05 00:13:50]

The perf script output doesn't say what the sampling frequency is. Maybe there's
some other way to get at that?

Personally, I prefer knowing the number of samples in my profiles to the number
of ms, but I think it'd be good to give control over that if we have the
information.

[vmiura, 2014/04/08 19:33:50]

In my experience the perf sampling interval is quite variable and hard to
convert to time.

Perf has a "period" field in every sample, that has to be used as a weight. 
This is how "perf" calculates %ages.

perf script doesn't support the "period" field, but I added it locally.

+
+def strip_to_last_paren(line):

[eseidel, 2014/04/05 00:03:13]

I'm surprised you didn't just use a regexp to match the whole line?

+  last_paren_index = line.rfind('(')
+  if last_paren_index == -1:
+    return line
+  return line[:last_paren_index]
+
+def extract_function_name(line):
+  # This information from the stack doesn't seem terribly useful.
+  line = line.replace('(anonymous namespace)::', '')
+  line = line.replace('non-virtual thunk to ', '')
+
+  # Strip executable name.
+  line = strip_to_last_paren(line)
+  # Strip function arguments.

[eseidel, 2014/04/05 00:03:13]

Yeah, I think a regexp would be more readable, maybe?

[ojan, 2014/04/05 00:13:50]

I had a lot of trouble coming up with a regexp that did what I wanted...so I
gave up and wrote this. Open to suggestions.

+  line = strip_to_last_paren(line)
+
+  line = line.strip()
+  line = re.sub('\s+', ' ', line)
+
+  first_space_index = line.find(' ')
+  if first_space_index == -1:
+    # Unsymbolized addresses.
+    return line
+  return line[first_space_index + 1:]
+
+def collapse_perf_script_output(lines):
+  collapsed_lines = {}
+  stack_so_far = []
+  thread_id = ''
+
+  for line in lines:
+    line = line.strip()
+
+    if not line:
+      if stack_so_far:
+        stack = ';'.join(stack_so_far)
+        collapsed_lines[thread_id][stack] = (
+          collapsed_lines[thread_id].setdefault(stack, 0) + 1)
+      stack_so_far = []
+      continue
+
+    if line[0] == '#':
+      continue
+
+    match_header = re.match('\w+\ (\w+)\ cycles:\s*$', line)
+    if match_header:
+      thread_id = match_header.group(1)
+      if not thread_id in collapsed_lines:
+        collapsed_lines[thread_id] = {}
+      continue
+
+    stack_so_far.insert(0, extract_function_name(line))
+
+  return collapsed_lines
+
+def add_sample(root, thread_id, current_stack, start_time, end_time,
+    original_stack):
+  node_so_far = root
+  for function in current_stack:
+    # Can get the same stack on different threads, so identify samples by
+    # combination of function name and thread_id.
+    key = function + ';' + thread_id
+    if key in node_so_far:
+      node_so_far[key]['end_time'] = end_time
+    else:
+      node_so_far[key] = {
+        'children': {},
+        'start_time': start_time,
+        'end_time': end_time,
+      }
+    node_so_far = node_so_far[key]['children']
+
+def compute_tree(collapsed_lines):
+  total_samples_per_thread = {}
+  total_samples_for_all_threads = 0
+  tree = {}
+
+  for thread_id in collapsed_lines:
+    for stack in sorted(collapsed_lines[thread_id].iterkeys()):
+      samples = collapsed_lines[thread_id][stack]
+      total_samples_for_thread = total_samples_per_thread.setdefault(
+        thread_id, 0)
+      add_sample(tree, thread_id, stack.split(';'),
+        total_samples_for_thread, total_samples_for_thread + samples,
+        stack)
+      total_samples_per_thread[thread_id] += samples
+      total_samples_for_all_threads += samples
+
+  return tree, total_samples_for_all_threads, total_samples_per_thread
+
+def json_for_subtree(node, trace_data, total_samples_for_all_threads,
+    total_samples_per_thread):
+  for key in sorted(node.iterkeys()):
+    function, thread_id = key.split(';')
+    start_time = int(node[key]['start_time'])
+    end_time = int(node[key]['end_time'])
+    duration = end_time - start_time
+    process_percent = '%2.2f%%' % (
+      100 * float(duration) / total_samples_for_all_threads)
+    thread_percent = '%2.2f%%' % (
+      100 * float(duration) / total_samples_per_thread[thread_id])
+
+    # FIXME: extract out process IDs.
+    children = node[key]['children']
+
+    # If there are no children, we can use a Complete event instead two
+    # Duration events.
+    if not children:
+      trace_data.append({

[eseidel, 2014/04/05 00:05:09]

Crazy.  When I started down this path I just used immediate events and didn't
try to build a tree in the tracefile corresponding to teh stack traces.  I guess
that's kinda neat though, but I would expec these stacks to be very deep.

[ojan, 2014/04/05 00:13:50]

What are immediate events?

[dsinclair, 2014/04/08 02:28:36]

Immediate events are drawn as a line, instead of a block in the UI. There are 3
types, global, process and thread. The type, bascally, describes how tall the
line is. A global line is drawn the height of the UI, the process lines are a
full process block and a thread line will be one slice high.


https://docs.google.com/a/chromium.org/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYM...

[ojan, 2014/04/08 19:38:40]

The heading fragment doesn't seem to work. Searching the doc for "immediate"
doesn't find any hits.

In either case, from your description of how they're drawn, I'm not sure why
we'd want to use immediate events here. IMO, the whole point of this is to get
the tree view of the samples.

[dsinclair, 2014/04/08 19:42:44]

Sorry, I should use the right words, we call them instant events, in the
trace-viewer side.

+        "pid": 1,
+        "tid": thread_id,
+        "name": function,
+        "ts": start_time,
+        "dur": duration,
+        "ph": "X",
+        "args": {
+          "process percent": process_percent,
+          "thread percent": thread_percent
+        },
+      })
+      continue
+
+    trace_data.append({

[dsinclair, 2014/04/08 02:28:36]

I think, although I maybe mistaken, you could use a complete event here as well.
As long as the timestamps are in the right order I think it will do the UI
correctly. (Although, you'd need to test it to be sure)

[ojan, 2014/04/08 19:38:40]

I'm not sure what you're suggesting...how would the children be nested beneath
this function if using a complete event? Or are you just suggesting changing the
phase to "X"?

[dsinclair, 2014/04/08 19:42:44]

We create the nested slices based on timestamps not based on nesting. I believe
you could just output a "ph": "X" here and drop the "ph": "E" event below.  (It
doesn't really matter all X events do is decrease the number of events we have
to emit, it is functionally equivalent to a B/E pair for one X event.)

+      "pid": 1,
+      "tid": thread_id,
+      "name": function,
+      "ts": start_time,
+      "ph": "B",
+    })
+
+    json_for_subtree(children, trace_data, total_samples_for_all_threads,
+      total_samples_per_thread)
+
+    trace_data.append({
+      "pid": 1,
+      "tid": thread_id,
+      "name": function,
+      "ts": end_time,
+      "ph": "E",
+      "args": {
+        "process percent": process_percent,
+        "thread percent": thread_percent
+      },
+    })
+
+def stringified_json_output(lines):
+  tree, total_samples_for_all_threads, total_samples_per_thread = (
+    compute_tree(collapse_perf_script_output(lines)))
+  trace_data = []
+  json_for_subtree(tree, trace_data, total_samples_for_all_threads,
+    total_samples_per_thread)
+  return json.dumps(trace_data, separators=(',',':'))
+
+if __name__ == "__main__":
+  print stringified_json_output(sys.stdin.readlines())