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