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
5import json
6import logging
7import re
8import signal
9import subprocess
10import sys
11import tempfile
12
13from telemetry.core.platform import profiler
14from 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
46def _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
138def _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
162class _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
199class 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