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