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