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