catapult/telemetry/telemetry/internal/platform/profiler/strace_profiler.py

# Copyright 2013 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 logging
import re
import signal
import subprocess
import sys
import tempfile

from telemetry.internal.platform import profiler
from telemetry.timeline import model
from telemetry.timeline import trace_data as trace_data_module

# Parses one line of strace output, for example:
# 6052  1311456063.159722 read(8, "\1\0\0\0\0\0\0\0", 8) = 8 <0.000022>
_STRACE_LINE_RE = re.compile(
    r'^(?P<tid>\d+)\s+'
    r'(?P<ts>\d+)'
    r'(?P<micro>.\d+)\s+'
    r'(?P<func>.*?)'
    r'[(](?P<args>.*?)[)]\s+=\s+'
    r'(?P<ret>.*?)\s+'
    r'<(?P<dur>[\d.]+)>$')

_UNFINISHED_LINE_RE = re.compile(
    r'^(?P<tid>\d+)\s+'
    r'(?P<line>.*?)'
    r'<unfinished ...>$')

_RESUMED_LINE_RE = re.compile(
    r'^(?P<tid>\d+)\s+'
    r'(?P<ts>\d+)'
    r'(?P<micro>.\d+)\s+'
    r'<[.][.][.]\s(?P<func>.*?)\sresumed>'
    r'(?P<line>.*?)$')

_KILLED_LINE_RE = re.compile(
    r'^(?P<tid>\d+)\s+'
    r'(?P<ts>\d+)'
    r'(?P<micro>.\d+)\s+'
    r'[+][+][+] killed by SIGKILL [+][+][+]$')


def _StraceToChromeTrace(pid, infile):
  """Returns chrometrace json format for |infile| strace output."""
  # Map of fd:file_name for open file descriptors. Useful for displaying
  # file name instead of the descriptor number.
  fd_map = {}

  # Map of tid:interrupted_call for the interrupted call on each thread. It is
  # possible to context switch during a system call. In this case we must
  # match up the lines.
  interrupted_call_map = {}

  out = []
  with open(infile, 'r') as f:
    for line in f.readlines():
      # Ignore kill lines for now.
      m = _KILLED_LINE_RE.match(line)
      if m:
        continue

      # If this line is interrupted, then remember it and continue.
      m = _UNFINISHED_LINE_RE.match(line)
      if m:
        assert m.group('tid') not in interrupted_call_map
        interrupted_call_map[m.group('tid')] = line
        continue

      # If this is a resume of a previous line, stitch it together.
      interrupted = False
      m = _RESUMED_LINE_RE.match(line)
      if m:
        interrupted = True
        assert m.group('tid') in interrupted_call_map
        line = interrupted_call_map[m.group('tid')].replace(
            '<unfinished ...>', m.group('line'))
        del interrupted_call_map[m.group('tid')]

      # At this point we can do a normal match.
      m = _STRACE_LINE_RE.match(line)
      if not m:
        if ('exit' not in line and
            'Profiling timer expired' not in line and
            '<unavailable>' not in line):
          logging.warn('Failed to parse line: %s' % line)
        continue

      ts_begin = int(1000000 * (int(m.group('ts')) + float(m.group('micro'))))
      ts_end = ts_begin + int(1000000 * float(m.group('dur')))
      tid = int(m.group('tid'))
      function_name = unicode(m.group('func'), errors='ignore')
      function_args = unicode(m.group('args'), errors='ignore')
      ret = unicode(m.group('ret'), errors='ignore')
      cat = 'strace'

      possible_fd_arg = None
      first_arg = function_args.split(',')[0]
      if first_arg and first_arg.strip().isdigit():
        possible_fd_arg = first_arg.strip()

      if function_name == 'open' and ret.isdigit():
        # 1918  1311606151.649379 open("/foo/bar.so", O_RDONLY) = 7 <0.000088>
        fd_map[ret] = first_arg

      args = {
          'args': function_args,
          'ret': ret,
          }
      if interrupted:
        args['interrupted'] = True
      if possible_fd_arg and possible_fd_arg in fd_map:
        args['fd%s' % first_arg] = fd_map[possible_fd_arg]

      out.append({
          'cat': cat,
          'pid': pid,
          'tid': tid,
          'ts': ts_begin,
          'ph': 'B',  # Begin
          'name': function_name,
          })
      out.append({
          'cat': cat,
          'pid': pid,
          'tid': tid,
          'ts': ts_end,
          'ph': 'E',  # End
          'name': function_name,
          'args': args,
          })

  return out


def _GenerateTraceMetadata(timeline_model):
  out = []
  for process in timeline_model.processes:
    out.append({
        'name': 'process_name',
        'ph': 'M',  # Metadata
        'pid': process,
        'args': {
          'name': timeline_model.processes[process].name
          }
        })
    for thread in timeline_model.processes[process].threads:
      out.append({
          'name': 'thread_name',
          'ph': 'M',  # Metadata
          'pid': process,
          'tid': thread,
          'args': {
            'name': timeline_model.processes[process].threads[thread].name
            }
          })
  return out


class _SingleProcessStraceProfiler(object):
  """An internal class for using perf for a given process."""
  def __init__(self, pid, output_file, platform_backend):
    self._pid = pid
    self._platform_backend = platform_backend
    self._output_file = output_file
    self._tmp_output_file = tempfile.NamedTemporaryFile('w', 0)
    self._proc = subprocess.Popen(
        ['strace', '-ttt', '-f', '-T', '-p', str(pid), '-o', output_file],
        stdout=self._tmp_output_file, stderr=subprocess.STDOUT)

  def CollectProfile(self):
    if ('renderer' in self._output_file and
        not self._platform_backend.GetCommandLine(self._pid)):
      logging.warning('Renderer was swapped out during profiling. '
                      'To collect a full profile rerun with '
                      '"--extra-browser-args=--single-process"')
    self._proc.send_signal(signal.SIGINT)
    exit_code = self._proc.wait()
    try:
      if exit_code:
        raise Exception('strace failed with exit code %d. Output:\n%s' % (
                        exit_code, self._GetStdOut()))
    finally:
      self._tmp_output_file.close()

    return _StraceToChromeTrace(self._pid, self._output_file)

  def _GetStdOut(self):
    self._tmp_output_file.flush()
    try:
      with open(self._tmp_output_file.name) as f:
        return f.read()
    except IOError:
      return ''


class StraceProfiler(profiler.Profiler):

  def __init__(self, browser_backend, platform_backend, output_path, state):
    super(StraceProfiler, self).__init__(
        browser_backend, platform_backend, output_path, state)
    assert self._browser_backend.supports_tracing
    self._browser_backend.browser.StartTracing(None, timeout=10)
    process_output_file_map = self._GetProcessOutputFileMap()
    self._process_profilers = []
    self._output_file = output_path + '.json'
    for pid, output_file in process_output_file_map.iteritems():
      if 'zygote' in output_file:
        continue
      self._process_profilers.append(
          _SingleProcessStraceProfiler(pid, output_file, platform_backend))

  @classmethod
  def name(cls):
    return 'strace'

  @classmethod
  def is_supported(cls, browser_type):
    if sys.platform != 'linux2':
      return False
    # TODO(tonyg): This should be supported on android and cros.
    if (browser_type.startswith('android') or
       browser_type.startswith('cros')):
      return False
    return True

  @classmethod
  def CustomizeBrowserOptions(cls, browser_type, options):
    options.AppendExtraBrowserArgs([
        '--no-sandbox',
        '--allow-sandbox-debugging'
    ])

  def CollectProfile(self):
    print 'Processing trace...'

    out_json = []

    for single_process in self._process_profilers:
      out_json.extend(single_process.CollectProfile())

    trace_data_builder = trace_data_module.TraceDataBuilder()
    self._browser_backend.browser.StopTracing(trace_data_builder)
    timeline_model = model.TimelineModel(trace_data_builder.AsData())
    out_json.extend(_GenerateTraceMetadata(timeline_model))

    with open(self._output_file, 'w') as f:
      f.write(json.dumps(out_json, separators=(',', ':')))

    print 'Trace saved as %s' % self._output_file
    print 'To view, open in chrome://tracing'
    return [self._output_file]