Chris Craik | ad0b04f | 2015-07-21 13:44:22 -0700 | [diff] [blame] | 1 | # Copyright (c) 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 | |
| 5 | import Queue |
| 6 | import re |
| 7 | import subprocess |
| 8 | import sys |
| 9 | import threading |
| 10 | import time |
| 11 | import zlib |
| 12 | |
| 13 | import systrace_agent |
| 14 | import util |
| 15 | |
| 16 | # Text that ADB sends, but does not need to be displayed to the user. |
| 17 | ADB_IGNORE_REGEXP = r'^capturing trace\.\.\. done|^capturing trace\.\.\.' |
| 18 | # The number of seconds to wait on output from ADB. |
| 19 | ADB_STDOUT_READ_TIMEOUT = 0.2 |
| 20 | # The adb shell command to initiate a trace. |
| 21 | ATRACE_BASE_ARGS = ['atrace'] |
| 22 | # If a custom list of categories is not specified, traces will include |
| 23 | # these categories (if available on the device). |
| 24 | DEFAULT_CATEGORIES = 'sched gfx view dalvik webview input disk am wm'.split() |
| 25 | # The command to list trace categories. |
| 26 | LIST_CATEGORIES_ARGS = ATRACE_BASE_ARGS + ['--list_categories'] |
| 27 | # Minimum number of seconds between displaying status updates. |
| 28 | MIN_TIME_BETWEEN_STATUS_UPDATES = 0.2 |
| 29 | # ADB sends this text to indicate the beginning of the trace data. |
| 30 | TRACE_START_REGEXP = r'TRACE\:' |
| 31 | # Plain-text trace data should always start with this string. |
| 32 | TRACE_TEXT_HEADER = '# tracer' |
| 33 | |
| 34 | # This list is based on the tags in frameworks/native/include/utils/Trace.h for |
| 35 | # legacy platform. |
| 36 | LEGACY_TRACE_TAG_BITS = ( |
| 37 | ('gfx', 1<<1), |
| 38 | ('input', 1<<2), |
| 39 | ('view', 1<<3), |
| 40 | ('webview', 1<<4), |
| 41 | ('wm', 1<<5), |
| 42 | ('am', 1<<6), |
| 43 | ('sm', 1<<7), |
| 44 | ('audio', 1<<8), |
| 45 | ('video', 1<<9), |
| 46 | ('camera', 1<<10), |
| 47 | ) |
| 48 | |
| 49 | |
| 50 | def try_create_agent(options, categories): |
| 51 | if options.from_file is not None: |
| 52 | return AtraceAgent(options, categories) |
| 53 | |
| 54 | device_sdk_version = util.get_device_sdk_version() |
| 55 | if device_sdk_version >= 18: |
| 56 | return AtraceAgent(options, categories) |
| 57 | elif device_sdk_version >= 16: |
| 58 | return AtraceLegacyAgent(options, categories) |
| 59 | |
| 60 | |
| 61 | class AtraceAgent(systrace_agent.SystraceAgent): |
| 62 | def __init__(self, options, categories): |
| 63 | super(AtraceAgent, self).__init__(options, categories) |
| 64 | self._expect_trace = False |
| 65 | self._adb = None |
| 66 | self._trace_data = None |
| 67 | |
| 68 | def start(self): |
| 69 | tracer_args = self._construct_trace_command() |
| 70 | try: |
| 71 | self._adb = subprocess.Popen(tracer_args, stdout=subprocess.PIPE, |
| 72 | stderr=subprocess.PIPE) |
| 73 | except OSError as error: |
| 74 | print >> sys.stderr, ( |
| 75 | 'The command "%s" failed with the following error:' % |
| 76 | ' '.join(tracer_args)) |
| 77 | print >> sys.stderr, ' ', error |
| 78 | sys.exit(1) |
| 79 | |
| 80 | def collect_result(self): |
| 81 | trace_data = self._collect_trace_data(); |
| 82 | if self._expect_trace: |
| 83 | self._trace_data = self._preprocess_trace_data(trace_data); |
| 84 | |
| 85 | def expect_trace(self): |
| 86 | return self._expect_trace |
| 87 | |
| 88 | def get_trace_data(self): |
| 89 | return self._trace_data |
| 90 | |
| 91 | def get_class_name(self): |
| 92 | return 'trace-data' |
| 93 | |
| 94 | def _construct_list_categories_command(self): |
| 95 | return util.construct_adb_shell_command( |
| 96 | LIST_CATEGORIES_ARGS, self._options.device_serial) |
| 97 | |
| 98 | def _construct_extra_trace_command(self): |
| 99 | extra_args = [] |
| 100 | if self._options.app_name is not None: |
| 101 | extra_args.extend(['-a', self._options.app_name]) |
| 102 | |
| 103 | if self._options.kfuncs is not None: |
| 104 | extra_args.extend(['-k', self._options.kfuncs]) |
| 105 | |
| 106 | if not self._categories: |
| 107 | self._categories = get_default_categories(self._options.device_serial) |
| 108 | extra_args.extend(self._categories) |
| 109 | return extra_args |
| 110 | |
| 111 | def _construct_trace_command(self): |
| 112 | """Builds a command-line used to invoke a trace process. |
| 113 | |
| 114 | Returns: |
| 115 | A tuple where the first element is an array of command-line arguments, and |
| 116 | the second element is a boolean which will be true if the commend will |
| 117 | stream trace data. |
| 118 | """ |
| 119 | if self._options.list_categories: |
| 120 | tracer_args = self._construct_list_categories_command() |
| 121 | self._expect_trace = False |
| 122 | elif self._options.from_file is not None: |
| 123 | tracer_args = ['cat', self._options.from_file] |
| 124 | self._expect_trace = True |
| 125 | else: |
| 126 | atrace_args = ATRACE_BASE_ARGS[:] |
| 127 | self._expect_trace = True |
| 128 | if self._options.compress_trace_data: |
| 129 | atrace_args.extend(['-z']) |
| 130 | |
| 131 | if ((self._options.trace_time is not None) |
| 132 | and (self._options.trace_time > 0)): |
| 133 | atrace_args.extend(['-t', str(self._options.trace_time)]) |
| 134 | |
| 135 | if ((self._options.trace_buf_size is not None) |
| 136 | and (self._options.trace_buf_size > 0)): |
| 137 | atrace_args.extend(['-b', str(self._options.trace_buf_size)]) |
| 138 | extra_args = self._construct_extra_trace_command() |
| 139 | atrace_args.extend(extra_args) |
| 140 | |
| 141 | if self._options.fix_threads: |
| 142 | atrace_args.extend([';', 'ps', '-t']) |
| 143 | tracer_args = util.construct_adb_shell_command( |
| 144 | atrace_args, self._options.device_serial) |
| 145 | |
| 146 | return tracer_args |
| 147 | |
| 148 | def _collect_trace_data(self): |
| 149 | # Read the output from ADB in a worker thread. This allows us to monitor |
| 150 | # the progress of ADB and bail if ADB becomes unresponsive for any reason. |
| 151 | |
| 152 | # Limit the stdout_queue to 128 entries because we will initially be reading |
| 153 | # one byte at a time. When the queue fills up, the reader thread will |
| 154 | # block until there is room in the queue. Once we start downloading the |
| 155 | # trace data, we will switch to reading data in larger chunks, and 128 |
| 156 | # entries should be plenty for that purpose. |
| 157 | stdout_queue = Queue.Queue(maxsize=128) |
| 158 | stderr_queue = Queue.Queue() |
| 159 | |
| 160 | if self._expect_trace: |
| 161 | # Use stdout.write() (here and for the rest of this function) instead |
| 162 | # of print() to avoid extra newlines. |
| 163 | sys.stdout.write('Capturing trace...') |
| 164 | |
| 165 | # Use a chunk_size of 1 for stdout so we can display the output to |
| 166 | # the user without waiting for a full line to be sent. |
| 167 | stdout_thread = FileReaderThread(self._adb.stdout, stdout_queue, |
| 168 | text_file=False, chunk_size=1) |
| 169 | stderr_thread = FileReaderThread(self._adb.stderr, stderr_queue, |
| 170 | text_file=True) |
| 171 | stdout_thread.start() |
| 172 | stderr_thread.start() |
| 173 | |
| 174 | # Holds the trace data returned by ADB. |
| 175 | trace_data = [] |
| 176 | # Keep track of the current line so we can find the TRACE_START_REGEXP. |
| 177 | current_line = '' |
| 178 | # Set to True once we've received the TRACE_START_REGEXP. |
| 179 | reading_trace_data = False |
| 180 | |
| 181 | last_status_update_time = time.time() |
| 182 | |
| 183 | while (stdout_thread.isAlive() or stderr_thread.isAlive() or |
| 184 | not stdout_queue.empty() or not stderr_queue.empty()): |
| 185 | if self._expect_trace: |
| 186 | last_status_update_time = status_update(last_status_update_time) |
| 187 | |
| 188 | while not stderr_queue.empty(): |
| 189 | # Pass along errors from adb. |
| 190 | line = stderr_queue.get() |
| 191 | sys.stderr.write(line) |
| 192 | |
| 193 | # Read stdout from adb. The loop exits if we don't get any data for |
| 194 | # ADB_STDOUT_READ_TIMEOUT seconds. |
| 195 | while True: |
| 196 | try: |
| 197 | chunk = stdout_queue.get(True, ADB_STDOUT_READ_TIMEOUT) |
| 198 | except Queue.Empty: |
| 199 | # Didn't get any data, so exit the loop to check that ADB is still |
| 200 | # alive and print anything sent to stderr. |
| 201 | break |
| 202 | |
| 203 | if reading_trace_data: |
| 204 | # Save, but don't print, the trace data. |
| 205 | trace_data.append(chunk) |
| 206 | else: |
| 207 | if not self._expect_trace: |
| 208 | sys.stdout.write(chunk) |
| 209 | else: |
| 210 | # Buffer the output from ADB so we can remove some strings that |
| 211 | # don't need to be shown to the user. |
| 212 | current_line += chunk |
| 213 | if re.match(TRACE_START_REGEXP, current_line): |
| 214 | # We are done capturing the trace. |
| 215 | sys.stdout.write('Done.\n') |
| 216 | # Now we start downloading the trace data. |
| 217 | sys.stdout.write('Downloading trace...') |
| 218 | current_line = '' |
| 219 | # Use a larger chunk size for efficiency since we no longer |
| 220 | # need to worry about parsing the stream. |
| 221 | stdout_thread.set_chunk_size(4096) |
| 222 | reading_trace_data = True |
| 223 | elif chunk == '\n' or chunk == '\r': |
| 224 | # Remove ADB output that we don't care about. |
| 225 | current_line = re.sub(ADB_IGNORE_REGEXP, '', current_line) |
| 226 | if len(current_line) > 1: |
| 227 | # ADB printed something that we didn't understand, so show it |
| 228 | # it to the user (might be helpful for debugging). |
| 229 | sys.stdout.write(current_line) |
| 230 | # Reset our current line. |
| 231 | current_line = '' |
| 232 | |
| 233 | if self._expect_trace: |
| 234 | if reading_trace_data: |
| 235 | # Indicate to the user that the data download is complete. |
| 236 | sys.stdout.write('Done.\n') |
| 237 | else: |
| 238 | # We didn't receive the trace start tag, so something went wrong. |
| 239 | sys.stdout.write('ERROR.\n') |
| 240 | # Show any buffered ADB output to the user. |
| 241 | current_line = re.sub(ADB_IGNORE_REGEXP, '', current_line) |
| 242 | if current_line: |
| 243 | sys.stdout.write(current_line) |
| 244 | sys.stdout.write('\n') |
| 245 | |
| 246 | # The threads should already have stopped, so this is just for cleanup. |
| 247 | stdout_thread.join() |
| 248 | stderr_thread.join() |
| 249 | |
| 250 | self._adb.stdout.close() |
| 251 | self._adb.stderr.close() |
| 252 | |
| 253 | # The adb process should be done since it's io pipes are closed. Call |
| 254 | # poll() to set the returncode. |
| 255 | self._adb.poll() |
| 256 | |
| 257 | if self._adb.returncode != 0: |
| 258 | print >> sys.stderr, ('The command "%s" returned error code %d.' % |
| 259 | (' '.join(tracer_args), self._adb.returncode)) |
| 260 | sys.exit(1) |
| 261 | |
| 262 | return trace_data |
| 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 | trace_data = ''.join(trace_data) |
| 273 | |
| 274 | if self._options.fix_threads: |
| 275 | # Extract the thread list dumped by ps. |
| 276 | trace_data, thread_names = extract_thread_list(trace_data) |
| 277 | |
| 278 | if trace_data: |
| 279 | trace_data = strip_and_decompress_trace(trace_data) |
| 280 | |
| 281 | if not trace_data: |
| 282 | print >> sys.stderr, ('No data was captured. Output file was not ' |
| 283 | 'written.') |
| 284 | sys.exit(1) |
| 285 | |
| 286 | if self._options.fix_threads: |
| 287 | trace_data = fix_thread_names(trace_data, thread_names) |
| 288 | |
| 289 | if self._options.fix_circular: |
| 290 | trace_data = fix_circular_traces(trace_data) |
| 291 | |
| 292 | return trace_data |
| 293 | |
| 294 | |
| 295 | class AtraceLegacyAgent(AtraceAgent): |
| 296 | def _construct_list_categories_command(self): |
| 297 | LEGACY_CATEGORIES = """ sched - CPU Scheduling |
| 298 | freq - CPU Frequency |
| 299 | idle - CPU Idle |
| 300 | load - CPU Load |
| 301 | disk - Disk I/O (requires root) |
| 302 | bus - Bus utilization (requires root) |
| 303 | workqueue - Kernel workqueues (requires root)""" |
| 304 | return ["echo", LEGACY_CATEGORIES] |
| 305 | |
| 306 | def start(self): |
| 307 | super(AtraceLegacyAgent, self).start() |
| 308 | if self.expect_trace(): |
| 309 | SHELL_ARGS = ['getprop', 'debug.atrace.tags.enableflags'] |
| 310 | output, return_code = util.run_adb_shell(SHELL_ARGS, self._options.device_serial) |
| 311 | flags = 0 |
| 312 | if return_code == 0: |
| 313 | try: |
| 314 | if output.startswith('0x'): |
| 315 | flags = int(output, 16) |
| 316 | elif output.startswith('0'): |
| 317 | flags = int(output, 8) |
| 318 | else: |
| 319 | flags = int(output) |
| 320 | except ValueError, e: |
| 321 | pass |
| 322 | |
| 323 | if flags: |
| 324 | tags = [] |
| 325 | for desc, bit in LEGACY_TRACE_TAG_BITS: |
| 326 | if bit & flags: |
| 327 | tags.append(desc) |
| 328 | categories = tags + self._categories |
| 329 | print 'Collecting data with following categories:', ' '.join(categories) |
| 330 | |
| 331 | def _construct_extra_trace_command(self): |
| 332 | extra_args = [] |
| 333 | if not self._categories: |
| 334 | self._categories = ['sched', ] |
| 335 | if 'sched' in self._categories: |
| 336 | extra_args.append('-s') |
| 337 | if 'freq' in self._categories: |
| 338 | extra_args.append('-f') |
| 339 | if 'idle' in self._categories: |
| 340 | extra_args.append('-i') |
| 341 | if 'load' in self._categories: |
| 342 | extra_args.append('-l') |
| 343 | if 'disk' in self._categories: |
| 344 | extra_args.append('-d') |
| 345 | if 'bus' in self._categories: |
| 346 | extra_args.append('-u') |
| 347 | if 'workqueue' in self._categories: |
| 348 | extra_args.append('-w') |
| 349 | |
| 350 | return extra_args |
| 351 | |
| 352 | |
| 353 | class FileReaderThread(threading.Thread): |
| 354 | """Reads data from a file/pipe on a worker thread. |
| 355 | |
| 356 | Use the standard threading. Thread object API to start and interact with the |
| 357 | thread (start(), join(), etc.). |
| 358 | """ |
| 359 | |
| 360 | def __init__(self, file_object, output_queue, text_file, chunk_size=-1): |
| 361 | """Initializes a FileReaderThread. |
| 362 | |
| 363 | Args: |
| 364 | file_object: The file or pipe to read from. |
| 365 | output_queue: A Queue.Queue object that will receive the data |
| 366 | text_file: If True, the file will be read one line at a time, and |
| 367 | chunk_size will be ignored. If False, line breaks are ignored and |
| 368 | chunk_size must be set to a positive integer. |
| 369 | chunk_size: When processing a non-text file (text_file = False), |
| 370 | chunk_size is the amount of data to copy into the queue with each |
| 371 | read operation. For text files, this parameter is ignored. |
| 372 | """ |
| 373 | threading.Thread.__init__(self) |
| 374 | self._file_object = file_object |
| 375 | self._output_queue = output_queue |
| 376 | self._text_file = text_file |
| 377 | self._chunk_size = chunk_size |
| 378 | assert text_file or chunk_size > 0 |
| 379 | |
| 380 | def run(self): |
| 381 | """Overrides Thread's run() function. |
| 382 | |
| 383 | Returns when an EOF is encountered. |
| 384 | """ |
| 385 | if self._text_file: |
| 386 | # Read a text file one line at a time. |
| 387 | for line in self._file_object: |
| 388 | self._output_queue.put(line) |
| 389 | else: |
| 390 | # Read binary or text data until we get to EOF. |
| 391 | while True: |
| 392 | chunk = self._file_object.read(self._chunk_size) |
| 393 | if not chunk: |
| 394 | break |
| 395 | self._output_queue.put(chunk) |
| 396 | |
| 397 | def set_chunk_size(self, chunk_size): |
| 398 | """Change the read chunk size. |
| 399 | |
| 400 | This function can only be called if the FileReaderThread object was |
| 401 | created with an initial chunk_size > 0. |
| 402 | Args: |
| 403 | chunk_size: the new chunk size for this file. Must be > 0. |
| 404 | """ |
| 405 | # The chunk size can be changed asynchronously while a file is being read |
| 406 | # in a worker thread. However, type of file can not be changed after the |
| 407 | # the FileReaderThread has been created. These asserts verify that we are |
| 408 | # only changing the chunk size, and not the type of file. |
| 409 | assert not self._text_file |
| 410 | assert chunk_size > 0 |
| 411 | self._chunk_size = chunk_size |
| 412 | |
| 413 | |
| 414 | def get_default_categories(device_serial): |
| 415 | categories_output, return_code = util.run_adb_shell(LIST_CATEGORIES_ARGS, |
| 416 | device_serial) |
| 417 | |
| 418 | if return_code == 0 and categories_output: |
| 419 | categories = [c.split('-')[0].strip() |
| 420 | for c in categories_output.splitlines()] |
| 421 | return [c for c in categories if c in DEFAULT_CATEGORIES] |
| 422 | |
| 423 | return [] |
| 424 | |
| 425 | |
| 426 | def status_update(last_update_time): |
| 427 | current_time = time.time() |
| 428 | if (current_time - last_update_time) >= MIN_TIME_BETWEEN_STATUS_UPDATES: |
| 429 | # Gathering a trace may take a while. Keep printing something so users |
| 430 | # don't think the script has hung. |
| 431 | sys.stdout.write('.') |
| 432 | sys.stdout.flush() |
| 433 | return current_time |
| 434 | |
| 435 | return last_update_time |
| 436 | |
| 437 | |
| 438 | def extract_thread_list(trace_data): |
| 439 | """Removes the thread list from the given trace data. |
| 440 | |
| 441 | Args: |
| 442 | trace_data: The raw trace data (before decompression). |
| 443 | Returns: |
| 444 | A tuple containing the trace data and a map of thread ids to thread names. |
| 445 | """ |
| 446 | threads = {} |
| 447 | parts = re.split('USER +PID +PPID +VSIZE +RSS +WCHAN +PC +NAME', |
| 448 | trace_data, 1) |
| 449 | if len(parts) == 2: |
| 450 | trace_data = parts[0] |
| 451 | for line in parts[1].splitlines(): |
| 452 | cols = line.split(None, 8) |
| 453 | if len(cols) == 9: |
| 454 | tid = int(cols[1]) |
| 455 | name = cols[8] |
| 456 | threads[tid] = name |
| 457 | |
| 458 | return (trace_data, threads) |
| 459 | |
| 460 | |
| 461 | def strip_and_decompress_trace(trace_data): |
| 462 | """Fixes new-lines and decompresses trace data. |
| 463 | |
| 464 | Args: |
| 465 | trace_data: The trace data returned by atrace. |
| 466 | Returns: |
| 467 | The decompressed trace data. |
| 468 | """ |
| 469 | # Collapse CRLFs that are added by adb shell. |
| 470 | if trace_data.startswith('\r\n'): |
| 471 | trace_data = trace_data.replace('\r\n', '\n') |
| 472 | elif trace_data.startswith('\r\r\n'): |
| 473 | # On windows, adb adds an extra '\r' character for each line. |
| 474 | trace_data = trace_data.replace('\r\r\n', '\n') |
| 475 | |
| 476 | # Skip the initial newline. |
| 477 | trace_data = trace_data[1:] |
| 478 | |
| 479 | if not trace_data.startswith(TRACE_TEXT_HEADER): |
| 480 | # No header found, so assume the data is compressed. |
| 481 | trace_data = zlib.decompress(trace_data) |
| 482 | |
| 483 | # Enforce Unix line-endings. |
| 484 | trace_data = trace_data.replace('\r', '') |
| 485 | |
| 486 | # Skip any initial newlines. |
| 487 | while trace_data and trace_data[0] == '\n': |
| 488 | trace_data = trace_data[1:] |
| 489 | |
| 490 | return trace_data |
| 491 | |
| 492 | |
| 493 | def fix_thread_names(trace_data, thread_names): |
| 494 | """Replaces thread ids with their names. |
| 495 | |
| 496 | Args: |
| 497 | trace_data: The atrace data. |
| 498 | thread_names: A mapping of thread ids to thread names. |
| 499 | Returns: |
| 500 | The updated trace data. |
| 501 | """ |
| 502 | def repl(m): |
| 503 | tid = int(m.group(2)) |
| 504 | if tid > 0: |
| 505 | name = thread_names.get(tid) |
| 506 | if name is None: |
| 507 | name = m.group(1) |
| 508 | if name == '<...>': |
| 509 | name = '<' + str(tid) + '>' |
| 510 | thread_names[tid] = name |
| 511 | return name + '-' + m.group(2) |
| 512 | else: |
| 513 | return m.group(0) |
| 514 | trace_data = re.sub(r'^\s*(\S+)-(\d+)', repl, trace_data, |
| 515 | flags=re.MULTILINE) |
| 516 | return trace_data |
| 517 | |
| 518 | |
| 519 | def fix_circular_traces(out): |
| 520 | """Fix inconsistentcies in traces due to circular buffering. |
| 521 | |
| 522 | The circular buffers are kept per CPU, so it is not guaranteed that the |
| 523 | beginning of a slice is overwritten before the end. To work around this, we |
| 524 | throw away the prefix of the trace where not all CPUs have events yet. |
| 525 | |
| 526 | Args: |
| 527 | out: The data to fix. |
| 528 | Returns: |
| 529 | The updated trace data. |
| 530 | """ |
| 531 | # If any of the CPU's buffers have filled up and |
| 532 | # older events have been dropped, the kernel |
| 533 | # emits markers of the form '##### CPU 2 buffer started ####' on |
| 534 | # the line before the first event in the trace on that CPU. |
| 535 | # |
| 536 | # No such headers are emitted if there were no overflows or the trace |
| 537 | # was captured with non-circular buffers. |
| 538 | buffer_start_re = re.compile(r'^#+ CPU \d+ buffer started', re.MULTILINE) |
| 539 | |
| 540 | start_of_full_trace = 0 |
| 541 | |
| 542 | while True: |
| 543 | result = buffer_start_re.search(out, start_of_full_trace + 1) |
| 544 | if result: |
| 545 | start_of_full_trace = result.start() |
| 546 | else: |
| 547 | break |
| 548 | |
| 549 | if start_of_full_trace > 0: |
| 550 | # Need to keep the header intact to make the importer happy. |
| 551 | end_of_header = re.search(r'^[^#]', out, re.MULTILINE).start() |
| 552 | out = out[:end_of_header] + out[start_of_full_trace:] |
| 553 | return out |