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