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