Home | History | Annotate | Download | only in profiler 
      1 # Copyright 2013 The Chromium Authors. All rights reserved.
      2 # Use of this source code is governed by a BSD-style license that can be
      3 # found in the LICENSE file.
      4 
      5 import json
      6 import logging
      7 import re
      8 import signal
      9 import subprocess
     10 import sys
     11 import tempfile
     12 
     13 from telemetry.core.platform import profiler
     14 from telemetry.timeline import model
     15 
     16 # Parses one line of strace output, for example:
     17 # 6052  1311456063.159722 read(8, "\1\0\0\0\0\0\0\0", 8) = 8 <0.000022>
     18 _STRACE_LINE_RE = re.compile(
     19     '^(?P<tid>\d+)\s+'
     20     '(?P<ts>\d+)'
     21     '(?P<micro>.\d+)\s+'
     22     '(?P<func>.*?)'
     23     '[(](?P<args>.*?)[)]\s+=\s+'
     24     '(?P<ret>.*?)\s+'
     25     '<(?P<dur>[\d.]+)>$')
     26 
     27 _UNFINISHED_LINE_RE = re.compile(
     28     '^(?P<tid>\d+)\s+'
     29     '(?P<line>.*?)'
     30     '<unfinished ...>$')
     31 
     32 _RESUMED_LINE_RE = re.compile(
     33     '^(?P<tid>\d+)\s+'
     34     '(?P<ts>\d+)'
     35     '(?P<micro>.\d+)\s+'
     36     '<[.][.][.]\s(?P<func>.*?)\sresumed>'
     37     '(?P<line>.*?)$')
     38 
     39 _KILLED_LINE_RE = re.compile(
     40     '^(?P<tid>\d+)\s+'
     41     '(?P<ts>\d+)'
     42     '(?P<micro>.\d+)\s+'
     43     '[+][+][+] killed by SIGKILL [+][+][+]$')
     44 
     45 
     46 def _StraceToChromeTrace(pid, infile):
     47   """Returns chrometrace json format for |infile| strace output."""
     48   # Map of fd:file_name for open file descriptors. Useful for displaying
     49   # file name instead of the descriptor number.
     50   fd_map = {}
     51 
     52   # Map of tid:interrupted_call for the interrupted call on each thread. It is
     53   # possible to context switch during a system call. In this case we must
     54   # match up the lines.
     55   interrupted_call_map = {}
     56 
     57   out = []
     58   with open(infile, 'r') as f:
     59     for line in f.readlines():
     60       # Ignore kill lines for now.
     61       m = _KILLED_LINE_RE.match(line)
     62       if m:
     63         continue
     64 
     65       # If this line is interrupted, then remember it and continue.
     66       m = _UNFINISHED_LINE_RE.match(line)
     67       if m:
     68         assert m.group('tid') not in interrupted_call_map
     69         interrupted_call_map[m.group('tid')] = line
     70         continue
     71 
     72       # If this is a resume of a previous line, stitch it together.
     73       interrupted = False
     74       m = _RESUMED_LINE_RE.match(line)
     75       if m:
     76         interrupted = True
     77         assert m.group('tid') in interrupted_call_map
     78         line = interrupted_call_map[m.group('tid')].replace(
     79             '<unfinished ...>', m.group('line'))
     80         del interrupted_call_map[m.group('tid')]
     81 
     82       # At this point we can do a normal match.
     83       m = _STRACE_LINE_RE.match(line)
     84       if not m:
     85         if ('exit' not in line and
     86             'Profiling timer expired' not in line and
     87             '<unavailable>' not in line):
     88           logging.warn('Failed to parse line: %s' % line)
     89         continue
     90 
     91       ts_begin = int(1000000 * (int(m.group('ts')) + float(m.group('micro'))))
     92       ts_end = ts_begin + int(1000000 * float(m.group('dur')))
     93       tid = int(m.group('tid'))
     94       function_name = unicode(m.group('func'), errors='ignore')
     95       function_args = unicode(m.group('args'), errors='ignore')
     96       ret = unicode(m.group('ret'), errors='ignore')
     97       cat = 'strace'
     98 
     99       possible_fd_arg = None
    100       first_arg = function_args.split(',')[0]
    101       if first_arg and first_arg.strip().isdigit():
    102         possible_fd_arg = first_arg.strip()
    103 
    104       if function_name == 'open' and ret.isdigit():
    105         # 1918  1311606151.649379 open("/foo/bar.so", O_RDONLY) = 7 <0.000088>
    106         fd_map[ret] = first_arg
    107 
    108       args = {
    109           'args': function_args,
    110           'ret': ret,
    111           }
    112       if interrupted:
    113         args['interrupted'] = True
    114       if possible_fd_arg and possible_fd_arg in fd_map:
    115         args['fd%s' % first_arg] = fd_map[possible_fd_arg]
    116 
    117       out.append({
    118           'cat': cat,
    119           'pid': pid,
    120           'tid': tid,
    121           'ts': ts_begin,
    122           'ph': 'B',  # Begin
    123           'name': function_name,
    124           })
    125       out.append({
    126           'cat': cat,
    127           'pid': pid,
    128           'tid': tid,
    129           'ts': ts_end,
    130           'ph': 'E',  # End
    131           'name': function_name,
    132           'args': args,
    133           })
    134 
    135   return out
    136 
    137 
    138 def _GenerateTraceMetadata(timeline_model):
    139   out = []
    140   for process in timeline_model.processes:
    141     out.append({
    142         'name': 'process_name',
    143         'ph': 'M',  # Metadata
    144         'pid': process,
    145         'args': {
    146           'name': timeline_model.processes[process].name
    147           }
    148         })
    149     for thread in timeline_model.processes[process].threads:
    150       out.append({
    151           'name': 'thread_name',
    152           'ph': 'M',  # Metadata
    153           'pid': process,
    154           'tid': thread,
    155           'args': {
    156             'name': timeline_model.processes[process].threads[thread].name
    157             }
    158           })
    159   return out
    160 
    161 
    162 class _SingleProcessStraceProfiler(object):
    163   """An internal class for using perf for a given process."""
    164   def __init__(self, pid, output_file, platform_backend):
    165     self._pid = pid
    166     self._platform_backend = platform_backend
    167     self._output_file = output_file
    168     self._tmp_output_file = tempfile.NamedTemporaryFile('w', 0)
    169     self._proc = subprocess.Popen(
    170         ['strace', '-ttt', '-f', '-T', '-p', str(pid), '-o', output_file],
    171         stdout=self._tmp_output_file, stderr=subprocess.STDOUT)
    172 
    173   def CollectProfile(self):
    174     if ('renderer' in self._output_file and
    175         not self._platform_backend.GetCommandLine(self._pid)):
    176       logging.warning('Renderer was swapped out during profiling. '
    177                       'To collect a full profile rerun with '
    178                       '"--extra-browser-args=--single-process"')
    179     self._proc.send_signal(signal.SIGINT)
    180     exit_code = self._proc.wait()
    181     try:
    182       if exit_code:
    183         raise Exception('strace failed with exit code %d. Output:\n%s' % (
    184                         exit_code, self._GetStdOut()))
    185     finally:
    186       self._tmp_output_file.close()
    187 
    188     return _StraceToChromeTrace(self._pid, self._output_file)
    189 
    190   def _GetStdOut(self):
    191     self._tmp_output_file.flush()
    192     try:
    193       with open(self._tmp_output_file.name) as f:
    194         return f.read()
    195     except IOError:
    196       return ''
    197 
    198 
    199 class StraceProfiler(profiler.Profiler):
    200 
    201   def __init__(self, browser_backend, platform_backend, output_path, state):
    202     super(StraceProfiler, self).__init__(
    203         browser_backend, platform_backend, output_path, state)
    204     assert self._browser_backend.supports_tracing
    205     self._browser_backend.StartTracing(None, 10)
    206     process_output_file_map = self._GetProcessOutputFileMap()
    207     self._process_profilers = []
    208     self._output_file = output_path + '.json'
    209     for pid, output_file in process_output_file_map.iteritems():
    210       if 'zygote' in output_file:
    211         continue
    212       self._process_profilers.append(
    213           _SingleProcessStraceProfiler(pid, output_file, platform_backend))
    214 
    215   @classmethod
    216   def name(cls):
    217     return 'strace'
    218 
    219   @classmethod
    220   def is_supported(cls, browser_type):
    221     if sys.platform != 'linux2':
    222       return False
    223     # TODO(tonyg): This should be supported on android and cros.
    224     if (browser_type.startswith('android') or
    225        browser_type.startswith('cros')):
    226       return False
    227     return True
    228 
    229   @classmethod
    230   def CustomizeBrowserOptions(cls, browser_type, options):
    231     options.AppendExtraBrowserArgs([
    232         '--no-sandbox',
    233         '--allow-sandbox-debugging'
    234     ])
    235 
    236   def CollectProfile(self):
    237     print 'Processing trace...'
    238 
    239     out_json = []
    240 
    241     for single_process in self._process_profilers:
    242       out_json.extend(single_process.CollectProfile())
    243 
    244     timeline_data = self._browser_backend.StopTracing()
    245     timeline_model = model.TimelineModel(timeline_data)
    246     out_json.extend(_GenerateTraceMetadata(timeline_model))
    247 
    248     with open(self._output_file, 'w') as f:
    249       f.write(json.dumps(out_json, separators=(',', ':')))
    250 
    251     print 'Trace saved as %s' % self._output_file
    252     print 'To view, open in chrome://tracing'
    253     return [self._output_file]
    254