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