• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
1# Copyright 2015 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 optparse
6import platform
7import re
8import sys
9import threading
10import zlib
11
12import py_utils
13
14from devil.android import device_utils
15from devil.android.sdk import version_codes
16from py_trace_event import trace_time as trace_time_module
17from systrace import trace_result
18from systrace import tracing_agents
19from systrace import util
20
21# Text that ADB sends, but does not need to be displayed to the user.
22ADB_IGNORE_REGEXP = r'^capturing trace\.\.\. done|^capturing trace\.\.\.'
23# The number of seconds to wait on output from ADB.
24ADB_STDOUT_READ_TIMEOUT = 0.2
25# The number of seconds to wait for large output from ADB.
26ADB_LARGE_OUTPUT_TIMEOUT = 600
27# The adb shell command to initiate a trace.
28ATRACE_BASE_ARGS = ['atrace']
29# If a custom list of categories is not specified, traces will include
30# these categories (if available on the device).
31DEFAULT_CATEGORIES = 'sched,freq,gfx,view,dalvik,webview,'\
32                     'input,disk,am,wm,rs,binder_driver'
33# The command to list trace categories.
34LIST_CATEGORIES_ARGS = ATRACE_BASE_ARGS + ['--list_categories']
35# Minimum number of seconds between displaying status updates.
36MIN_TIME_BETWEEN_STATUS_UPDATES = 0.2
37# ADB sends this text to indicate the beginning of the trace data.
38TRACE_START_REGEXP = r'TRACE\:'
39# Plain-text trace data should always start with this string.
40TRACE_TEXT_HEADER = '# tracer'
41_FIX_MISSING_TGIDS = True
42_FIX_CIRCULAR_TRACES = True
43
44
45def list_categories(config):
46  """List the possible trace event categories.
47
48  This function needs the tracing config since it needs to get the serial
49  number of the device to send a command to.
50
51  Args:
52      config: Tracing config.
53  """
54  devutils = device_utils.DeviceUtils(config.device_serial_number)
55  categories = devutils.RunShellCommand(
56      LIST_CATEGORIES_ARGS, check_return=True)
57
58  device_sdk_version = util.get_device_sdk_version()
59  if device_sdk_version < version_codes.MARSHMALLOW:
60    # work around platform bug where rs tag would corrupt trace until M(Api23)
61    categories = [c for c in categories if not re.match(r'^\s*rs\s*-', c)]
62
63  print '\n'.join(categories)
64  if not devutils.HasRoot():
65    print '\nNOTE: more categories may be available with adb root\n'
66
67
68def get_available_categories(config, device_sdk_version):
69  """Gets the list of atrace categories available for tracing.
70  Args:
71      config: Tracing config.
72      device_sdk_version: Sdk version int of device to be queried.
73  """
74  devutils = device_utils.DeviceUtils(config.device_serial_number)
75  categories_output = devutils.RunShellCommand(
76      LIST_CATEGORIES_ARGS, check_return=True)
77  categories = [c.split('-')[0].strip() for c in categories_output]
78
79  if device_sdk_version < version_codes.MARSHMALLOW:
80    # work around platform bug where rs tag would corrupt trace until M(Api23)
81    categories = [c for c in categories if c != 'rs']
82  return categories
83
84
85def try_create_agent(config):
86  """Create an Atrace agent.
87
88  Args:
89      config: Command line config.
90  """
91  if config.target != 'android':
92    return None
93  if config.from_file is not None:
94    return None
95
96  if not config.atrace_categories:
97    return None
98
99  # Check device SDK version.
100  device_sdk_version = util.get_device_sdk_version()
101  if device_sdk_version < version_codes.JELLY_BEAN_MR2:
102    print ('Device SDK versions < 18 (Jellybean MR2) not supported.\n'
103           'Your device SDK version is %d.' % device_sdk_version)
104    return None
105
106  return AtraceAgent(device_sdk_version)
107
108def _construct_extra_atrace_args(config, categories):
109  """Construct extra arguments (-a, -k, categories) for atrace command.
110
111  Args:
112      config: Tracing config.
113  """
114  extra_args = []
115
116  if config.app_name is not None:
117    extra_args.extend(['-a', config.app_name])
118
119  if config.kfuncs is not None:
120    extra_args.extend(['-k', config.kfuncs])
121
122  extra_args.extend(categories)
123  return extra_args
124
125def _construct_atrace_args(config, categories):
126  """Builds the command used to invoke a trace process.
127  Returns:
128    A tuple where the first element is an array of command arguments, and
129    the second element is a boolean which will be true if the command will
130    stream trace data.
131  """
132  atrace_args = ATRACE_BASE_ARGS[:]
133
134  if config.compress_trace_data:
135    atrace_args.extend(['-z'])
136
137  if (config.trace_time is not None) and (config.trace_time > 0):
138    atrace_args.extend(['-t', str(config.trace_time)])
139
140  if (config.trace_buf_size is not None) and (config.trace_buf_size > 0):
141    atrace_args.extend(['-b', str(config.trace_buf_size)])
142
143  elif 'webview' in categories and 'sched' in categories:
144    # https://crbug.com/814330: webview_startup sometimes exceeds the buffer
145    # limit, so doubling this.
146    atrace_args.extend(['-b', '8192'])
147
148  elif 'sched' in categories:
149    # 'sched' is a high-volume tag, double the default buffer size
150    # to accommodate that
151    atrace_args.extend(['-b', '4096'])
152  extra_args = _construct_extra_atrace_args(config, categories)
153
154  atrace_args.extend(extra_args)
155  return atrace_args
156
157
158class AtraceAgent(tracing_agents.TracingAgent):
159
160  def __init__(self, device_sdk_version):
161    super(AtraceAgent, self).__init__()
162    self._device_sdk_version = device_sdk_version
163    self._adb = None
164    self._trace_data = None
165    self._tracer_args = None
166    self._collection_thread = None
167    self._device_utils = None
168    self._device_serial_number = None
169    self._config = None
170    self._categories = None
171
172  def __repr__(self):
173    return 'atrace'
174
175  @py_utils.Timeout(tracing_agents.START_STOP_TIMEOUT)
176  def StartAgentTracing(self, config, timeout=None):
177    assert config.atrace_categories, 'Atrace categories are missing!'
178    self._config = config
179    self._categories = config.atrace_categories
180    if isinstance(self._categories, list):
181      self._categories = ','.join(self._categories)
182    avail_cats = get_available_categories(config, self._device_sdk_version)
183    unavailable = [x for x in self._categories.split(',') if
184        x not in avail_cats]
185    self._categories = [x for x in self._categories.split(',') if
186        x in avail_cats]
187    if unavailable:
188      print 'These categories are unavailable: ' + ' '.join(unavailable)
189    self._device_utils = device_utils.DeviceUtils(config.device_serial_number)
190    self._device_serial_number = config.device_serial_number
191    self._tracer_args = _construct_atrace_args(config,
192                                               self._categories)
193    self._device_utils.RunShellCommand(
194        self._tracer_args + ['--async_start'], check_return=True)
195    return True
196
197  def _collect_and_preprocess(self):
198    """Collects and preprocesses trace data.
199
200    Stores results in self._trace_data.
201    """
202    trace_data = self._collect_trace_data()
203    self._trace_data = self._preprocess_trace_data(trace_data)
204
205  @py_utils.Timeout(tracing_agents.START_STOP_TIMEOUT)
206  def StopAgentTracing(self, timeout=None):
207    """Stops tracing and starts collecting results.
208
209    To synchronously retrieve the results after calling this function,
210    call GetResults().
211    """
212    self._collection_thread = threading.Thread(
213        target=self._collect_and_preprocess)
214    self._collection_thread.start()
215    return True
216
217  @py_utils.Timeout(tracing_agents.GET_RESULTS_TIMEOUT)
218  def GetResults(self, timeout=None):
219    """Waits for collection thread to finish and returns trace results."""
220    self._collection_thread.join()
221    self._collection_thread = None
222    return trace_result.TraceResult('systemTraceEvents', self._trace_data)
223
224  def SupportsExplicitClockSync(self):
225    return True
226
227  def RecordClockSyncMarker(self, sync_id, did_record_sync_marker_callback):
228    """Records a clock sync marker.
229
230    Args:
231        sync_id: ID string for clock sync marker.
232    """
233    cmd = 'echo trace_event_clock_sync: name=%s >' \
234        ' /sys/kernel/debug/tracing/trace_marker' % sync_id
235    with self._device_utils.adb.PersistentShell(
236        self._device_serial_number) as shell:
237      t1 = trace_time_module.Now()
238      shell.RunCommand(cmd, close=True)
239      did_record_sync_marker_callback(t1, sync_id)
240
241  def _stop_collect_trace(self):
242    """Stops atrace.
243
244    Note that prior to Api 23, --async-stop may not actually stop tracing.
245    Thus, this uses a fallback method of running a zero-length synchronous
246    trace if tracing is still on."""
247    result = self._device_utils.RunShellCommand(
248        self._tracer_args + ['--async_stop'], raw_output=True,
249        large_output=True, check_return=True, timeout=ADB_LARGE_OUTPUT_TIMEOUT)
250    is_trace_enabled_file = '/sys/kernel/debug/tracing/tracing_on'
251
252    if self._device_sdk_version < version_codes.MARSHMALLOW:
253      if int(self._device_utils.ReadFile(is_trace_enabled_file)):
254        # tracing was incorrectly left on, disable it
255        self._device_utils.RunShellCommand(
256            self._tracer_args + ['-t 0'], check_return=True)
257
258    return result
259
260  def _collect_trace_data(self):
261    """Reads the output from atrace and stops the trace."""
262    result = self._stop_collect_trace()
263
264    data_start = re.search(TRACE_START_REGEXP, result)
265    if data_start:
266      data_start = data_start.end(0)
267    else:
268      raise IOError('Unable to get atrace data. Did you forget adb root?')
269    output = re.sub(ADB_IGNORE_REGEXP, '', result[data_start:])
270    return output
271
272  def _preprocess_trace_data(self, trace_data):
273    """Performs various processing on atrace data.
274
275    Args:
276      trace_data: The raw trace data.
277    Returns:
278      The processed trace data.
279    """
280    if trace_data:
281      trace_data = strip_and_decompress_trace(trace_data)
282
283    if not trace_data:
284      print >> sys.stderr, ('No data was captured.  Output file was not '
285                            'written.')
286      sys.exit(1)
287
288    if _FIX_MISSING_TGIDS:
289      # Gather proc data from device and patch tgids
290      procfs_dump = self._device_utils.RunShellCommand(
291          'echo -n /proc/[0-9]*/task/[0-9]*',
292          shell=True, check_return=True)[0].split(' ')
293      pid2_tgid = extract_tgids(procfs_dump)
294      trace_data = fix_missing_tgids(trace_data, pid2_tgid)
295
296    if _FIX_CIRCULAR_TRACES:
297      trace_data = fix_circular_traces(trace_data)
298
299    return trace_data
300
301def extract_tgids(trace_lines):
302  """Removes the procfs dump from the given trace text
303
304  Args:
305    trace_lines: The text portion of the trace
306
307  Returns:
308    a map of pids to their tgid.
309  """
310  tgid_2pid = {}
311  for line in trace_lines:
312    result = re.match('^/proc/([0-9]+)/task/([0-9]+)', line)
313    if result:
314      parent_pid, tgid = result.group(1, 2)
315      tgid_2pid[tgid] = parent_pid
316
317  return tgid_2pid
318
319
320def strip_and_decompress_trace(trace_data):
321  """Fixes new-lines and decompresses trace data.
322
323  Args:
324    trace_data: The trace data returned by atrace.
325  Returns:
326    The decompressed trace data.
327  """
328  # Collapse CRLFs that are added by adb shell.
329  if trace_data.startswith('\r\n'):
330    trace_data = trace_data.replace('\r\n', '\n')
331  elif trace_data.startswith('\r\r\n'):
332    # On windows, adb adds an extra '\r' character for each line.
333    trace_data = trace_data.replace('\r\r\n', '\n')
334
335  # Skip the initial newline.
336  if trace_data[0] == '\n':
337    trace_data = trace_data[1:]
338
339  if not trace_data.startswith(TRACE_TEXT_HEADER):
340    # No header found, so assume the data is compressed.
341    trace_data = zlib.decompress(trace_data)
342
343  # Enforce Unix line-endings.
344  trace_data = trace_data.replace('\r', '')
345
346  # Skip any initial newlines.
347  while trace_data and trace_data[0] == '\n':
348    trace_data = trace_data[1:]
349
350  return trace_data
351
352
353def fix_missing_tgids(trace_data, pid2_tgid):
354  """Replaces missing TGIDs from the trace data with those found in procfs
355
356  Args:
357    trace_data: the atrace data
358
359  Returns:
360    The updated trace data with missing TGIDs replaced with the correct TGID
361  """
362
363  def repl(m):
364    tid = m.group(2)
365    if (int(tid) > 0 and m.group(1) != '<idle>' and m.group(3) == '(-----)'
366        and tid in pid2_tgid):
367      # returns Proc_name-PID (TGID)
368      # Binder_2-381 (-----) becomes Binder_2-381 (128)
369      return m.group(1) + '-' + m.group(2) + ' ( ' + pid2_tgid[tid] + ')'
370
371    return m.group(0)
372
373  # matches something like:
374  # Binder_2-895 (-----)
375  trace_data = re.sub(r'^\s*(\S+)-(\d+)\s+(\(\S+\))', repl, trace_data,
376                      flags=re.MULTILINE)
377  return trace_data
378
379
380def fix_circular_traces(out):
381  """Fix inconsistentcies in traces due to circular buffering.
382
383  The circular buffers are kept per CPU, so it is not guaranteed that the
384  beginning of a slice is overwritten before the end. To work around this, we
385  throw away the prefix of the trace where not all CPUs have events yet.
386
387  Args:
388    out: The data to fix.
389  Returns:
390    The updated trace data.
391  """
392  # If any of the CPU's buffers have filled up and
393  # older events have been dropped, the kernel
394  # emits markers of the form '##### CPU 2 buffer started ####' on
395  # the line before the first event in the trace on that CPU.
396  #
397  # No such headers are emitted if there were no overflows or the trace
398  # was captured with non-circular buffers.
399  buffer_start_re = re.compile(r'^#+ CPU \d+ buffer started', re.MULTILINE)
400
401  start_of_full_trace = 0
402
403  while True:
404    result = buffer_start_re.search(out, start_of_full_trace + 1)
405    if result:
406      start_of_full_trace = result.start()
407    else:
408      break
409
410  if start_of_full_trace > 0:
411    # Need to keep the header intact to make the importer happy.
412    end_of_header = re.search(r'^[^#]', out, re.MULTILINE).start()
413    out = out[:end_of_header] + out[start_of_full_trace:]
414  return out
415
416
417class AtraceConfig(tracing_agents.TracingConfig):
418  def __init__(self, atrace_categories, trace_buf_size, kfuncs,
419               app_name, compress_trace_data, from_file,
420               device_serial_number, trace_time, target):
421    tracing_agents.TracingConfig.__init__(self)
422    self.atrace_categories = atrace_categories
423    self.trace_buf_size = trace_buf_size
424    self.kfuncs = kfuncs
425    self.app_name = app_name
426    # Trace compression is broken on Windows.
427    # TODO: Fix https://crbug.com/739751.
428    self.compress_trace_data = \
429        compress_trace_data and platform.system() != 'Windows'
430    self.from_file = from_file
431    self.device_serial_number = device_serial_number
432    self.trace_time = trace_time
433    self.target = target
434
435
436def add_options(parser):
437  options = optparse.OptionGroup(parser, 'Atrace options')
438  options.add_option('--atrace-categories', dest='atrace_categories',
439                     help='Select atrace categories with a comma-delimited '
440                     'list, e.g. --atrace-categories=cat1,cat2,cat3')
441  options.add_option('-k', '--ktrace', dest='kfuncs', action='store',
442                     help='specify a comma-separated list of kernel functions '
443                     'to trace')
444  options.add_option('--no-compress', dest='compress_trace_data',
445                     default=True, action='store_false',
446                     help='Tell the device not to send the trace data in '
447                     'compressed form.')
448  options.add_option('-a', '--app', dest='app_name', default=None,
449                     type='string', action='store',
450                     help='enable application-level tracing for '
451                     'comma-separated list of app cmdlines')
452  options.add_option('--from-file', dest='from_file',
453                     action='store', help='read the trace from a '
454                     'file (compressed) rather than running a '
455                     'live trace')
456  return options
457
458def get_config(options):
459  return AtraceConfig(options.atrace_categories,
460                      options.trace_buf_size, options.kfuncs,
461                      options.app_name, options.compress_trace_data,
462                      options.from_file, options.device_serial_number,
463                      options.trace_time, options.target)
464