Chromium Code Reviews| OLD | NEW |
|---|---|
| 1 # Copyright (c) 2015 The Chromium Authors. All rights reserved. | 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 | 2 # Use of this source code is governed by a BSD-style license that can be |
| 3 # found in the LICENSE file. | 3 # found in the LICENSE file. |
| 4 | 4 |
| 5 import Queue | |
| 6 import re | 5 import re |
| 7 import subprocess | 6 import subprocess |
| 8 import sys | 7 import sys |
| 9 import threading | 8 import threading |
| 10 import time | |
| 11 import zlib | 9 import zlib |
| 12 | 10 |
| 13 from systrace import systrace_agent | 11 from devil.android import device_utils |
| 14 from systrace import util | 12 from systrace import util |
| 13 from systrace.tracing_agents import TracingAgent, TraceResults | |
| 14 | |
| 15 #TODO(alexandermont): add "from py_trace_event import trace_time" | |
| 16 #after persistent shell CL lands | |
| 15 | 17 |
| 16 # Text that ADB sends, but does not need to be displayed to the user. | 18 # Text that ADB sends, but does not need to be displayed to the user. |
| 17 ADB_IGNORE_REGEXP = r'^capturing trace\.\.\. done|^capturing trace\.\.\.' | 19 ADB_IGNORE_REGEXP = r'^capturing trace\.\.\. done|^capturing trace\.\.\.' |
| 18 # The number of seconds to wait on output from ADB. | 20 # The number of seconds to wait on output from ADB. |
| 19 ADB_STDOUT_READ_TIMEOUT = 0.2 | 21 ADB_STDOUT_READ_TIMEOUT = 0.2 |
| 20 # The adb shell command to initiate a trace. | 22 # The adb shell command to initiate a trace. |
| 21 ATRACE_BASE_ARGS = ['atrace'] | 23 ATRACE_BASE_ARGS = ['atrace'] |
| 22 # If a custom list of categories is not specified, traces will include | 24 # If a custom list of categories is not specified, traces will include |
| 23 # these categories (if available on the device). | 25 # these categories (if available on the device). |
| 24 DEFAULT_CATEGORIES = 'sched gfx view dalvik webview input disk am wm'.split() | 26 DEFAULT_CATEGORIES = 'sched gfx view dalvik webview input disk am wm'.split() |
| (...skipping 18 matching lines...) Expand all Loading... | |
| 43 ('view', 1 << 3), | 45 ('view', 1 << 3), |
| 44 ('webview', 1 << 4), | 46 ('webview', 1 << 4), |
| 45 ('wm', 1 << 5), | 47 ('wm', 1 << 5), |
| 46 ('am', 1 << 6), | 48 ('am', 1 << 6), |
| 47 ('sm', 1 << 7), | 49 ('sm', 1 << 7), |
| 48 ('audio', 1 << 8), | 50 ('audio', 1 << 8), |
| 49 ('video', 1 << 9), | 51 ('video', 1 << 9), |
| 50 ('camera', 1 << 10), | 52 ('camera', 1 << 10), |
| 51 ) | 53 ) |
| 52 | 54 |
| 55 def list_categories(options): | |
| 56 devutils = device_utils.DeviceUtils(options.device_serial) | |
| 57 for line in devutils.RunShellCommand(LIST_CATEGORIES_ARGS): | |
| 58 print line | |
| 53 | 59 |
| 54 def try_create_agent(options, categories): | 60 def try_create_agent(options, categories): |
| 61 """Create an Atrace agent. | |
| 62 | |
| 63 Args: | |
| 64 options: Command line options. | |
| 65 categories: Trace categories to capture. | |
| 66 """ | |
| 55 if options.target != 'android': | 67 if options.target != 'android': |
| 56 return False | 68 return False |
| 57 if options.from_file is not None: | 69 if options.from_file is not None: |
| 70 return False | |
| 71 | |
| 72 # Check for supported versions | |
| 73 device_sdk_version = util.get_device_sdk_version() | |
| 74 if device_sdk_version <= 17: | |
| 75 print >> sys.stderr, ('Device SDK versions <= 17 not supported.\n' | |
| 76 'Your device SDK version is %d.' % device_sdk_version) | |
| 77 elif device_sdk_version <= 22 and options.boot: | |
| 78 print >> sys.stderr, ( | |
| 79 'Device SDK versions <= 22 do not support boot tracing.\n' | |
| 80 'Your device SDK version is %d.' % device_sdk_version) | |
| 81 | |
| 82 if options.boot: | |
| 83 return BootAgent(options, categories) | |
| 84 else: | |
| 58 return AtraceAgent(options, categories) | 85 return AtraceAgent(options, categories) |
| 59 | 86 |
| 60 device_sdk_version = util.get_device_sdk_version() | 87 class AtraceAgent(TracingAgent): |
| 61 if device_sdk_version >= 18: | |
| 62 if options.boot: | |
| 63 # atrace --async_stop, which is used by BootAgent, does not work properly | |
| 64 # on the device SDK version 22 or before. | |
| 65 if device_sdk_version <= 22: | |
| 66 print >> sys.stderr, ('--boot option does not work on the device SDK ' | |
| 67 'version 22 or before.\nYour device SDK version ' | |
| 68 'is %d.' % device_sdk_version) | |
| 69 sys.exit(1) | |
| 70 return BootAgent(options, categories) | |
| 71 else: | |
| 72 return AtraceAgent(options, categories) | |
| 73 elif device_sdk_version >= 16: | |
| 74 return AtraceLegacyAgent(options, categories) | |
| 75 | |
| 76 | |
| 77 class AtraceAgent(systrace_agent.SystraceAgent): | |
| 78 | 88 |
| 79 def __init__(self, options, categories): | 89 def __init__(self, options, categories): |
|
Zhen Wang
2016/03/29 18:53:40
Do not pass in options and categories. Only device
alexandermont
2016/03/30 01:04:24
Done
| |
| 80 super(AtraceAgent, self).__init__(options, categories) | 90 super(AtraceAgent, self).__init__(options, categories) |
| 81 self._expect_trace = False | |
| 82 self._adb = None | |
| 83 self._trace_data = None | 91 self._trace_data = None |
| 84 self._tracer_args = None | 92 self._tracer_args = None |
| 93 self._adb = None | |
| 94 self._collection_process = None | |
| 95 self._device_utils = device_utils.DeviceUtils(self._options.device_serial) | |
| 85 if not self._categories: | 96 if not self._categories: |
| 86 self._categories = get_default_categories(self._options.device_serial) | 97 self._categories = get_default_categories(self._options.device_serial) |
| 87 | 98 |
| 88 def start(self): | 99 def _StartAgentTracing_func(self): |
| 89 self._tracer_args = self._construct_trace_command() | 100 """Starts tracing.""" |
| 101 self._tracer_args = self._construct_trace_args() | |
| 102 self._device_utils.RunShellCommand(self._tracer_args + ['--async_start']) | |
| 103 return True | |
| 90 | 104 |
| 91 self._adb = do_popen(self._tracer_args) | 105 def _collect_and_preprocess(self): |
| 106 """Collects and preprocesses trace data.""" | |
| 107 trace_data = self._collect_trace_data() | |
| 108 self._trace_data = self._preprocess_trace_data(trace_data) | |
| 92 | 109 |
| 93 def collect_result(self): | 110 def _StopAgentTracing_func(self): |
| 94 trace_data = self._collect_trace_data() | 111 """Stops tracing and collect results asynchronously. |
| 95 if self._expect_trace: | |
| 96 self._trace_data = self._preprocess_trace_data(trace_data) | |
| 97 | 112 |
| 98 def expect_trace(self): | 113 Creates a new process that stops tracing, collects results, and |
| 99 return self._expect_trace | 114 records them in self._trace_data. Returns immediately, without |
| 115 waiting for data collection to finish. | |
| 116 """ | |
| 117 self._collection_process = threading.Thread( | |
| 118 target=self._collect_and_preprocess) | |
| 119 self._collection_process.start() | |
| 120 return True | |
| 100 | 121 |
| 101 def get_trace_data(self): | 122 def _GetResults_func(self): |
| 102 return self._trace_data | 123 """Returns trace results.""" |
| 124 self._collection_process.join() | |
| 125 self._collection_process = None | |
| 126 return TraceResults('systemTraceEvents', self._trace_data) | |
| 103 | 127 |
| 104 def get_class_name(self): | 128 def SupportsExplicitClockSync(self): |
| 105 return 'trace-data' | 129 """Returns whether or not this supports explicit clock sync.""" |
| 130 return False | |
| 131 #TODO(alexandermont): return True after persistent shell CL lands | |
| 106 | 132 |
| 107 def _construct_list_categories_command(self): | 133 def RecordClockSyncMarker(self, sync_id, did_record_sync_marker_callback): |
| 108 return util.construct_adb_shell_command( | 134 """Records a clock sync marker. |
| 109 LIST_CATEGORIES_ARGS, self._options.device_serial) | |
| 110 | 135 |
| 111 def _construct_extra_trace_command(self): | 136 Args: |
| 137 sync_id: ID string for clock sync marker. | |
| 138 """ | |
| 139 return | |
| 140 #TODO(alexandermont): put the functoin back after persistent shell CL lands | |
| 141 | |
| 142 def _construct_extra_trace_args(self): | |
| 143 """Construct extra arguments (-a and -k) for trace command.""" | |
| 112 extra_args = [] | 144 extra_args = [] |
| 113 if self._options.app_name is not None: | 145 if self._options.app_name is not None: |
| 114 extra_args.extend(['-a', self._options.app_name]) | 146 extra_args.extend(['-a', self._options.app_name]) |
| 115 | 147 |
| 116 if self._options.kfuncs is not None: | 148 if self._options.kfuncs is not None: |
| 117 extra_args.extend(['-k', self._options.kfuncs]) | 149 extra_args.extend(['-k', self._options.kfuncs]) |
| 118 | 150 |
| 119 extra_args.extend(self._categories) | 151 extra_args.extend(self._categories) |
| 120 return extra_args | 152 return extra_args |
| 121 | 153 |
| 122 def _construct_trace_command(self): | 154 def _construct_trace_args(self): |
| 123 """Builds a command-line used to invoke a trace process. | 155 """Builds a command-line used to invoke a trace process. |
| 124 | 156 |
| 125 Returns: | 157 Returns: |
| 126 A tuple where the first element is an array of command-line arguments, and | 158 A tuple where the first element is an array of command-line arguments, and |
| 127 the second element is a boolean which will be true if the commend will | 159 the second element is a boolean which will be true if the command will |
| 128 stream trace data. | 160 stream trace data. |
| 129 """ | 161 """ |
| 130 if self._options.list_categories: | 162 atrace_args = ATRACE_BASE_ARGS[:] |
| 131 tracer_args = self._construct_list_categories_command() | |
| 132 self._expect_trace = False | |
| 133 elif self._options.from_file is not None: | |
| 134 tracer_args = ['cat', self._options.from_file] | |
| 135 self._expect_trace = True | |
| 136 else: | |
| 137 atrace_args = ATRACE_BASE_ARGS[:] | |
| 138 self._expect_trace = True | |
| 139 if self._options.compress_trace_data: | |
| 140 atrace_args.extend(['-z']) | |
| 141 | 163 |
| 142 if ((self._options.trace_time is not None) | 164 if self._options.compress_trace_data: |
| 143 and (self._options.trace_time > 0)): | 165 atrace_args.extend(['-z']) |
| 144 atrace_args.extend(['-t', str(self._options.trace_time)]) | |
| 145 | 166 |
| 146 if ((self._options.trace_buf_size is not None) | 167 if ((self._options.trace_time is not None) |
| 147 and (self._options.trace_buf_size > 0)): | 168 and (self._options.trace_time > 0)): |
| 148 atrace_args.extend(['-b', str(self._options.trace_buf_size)]) | 169 atrace_args.extend(['-t', str(self._options.trace_time)]) |
| 149 elif 'sched' in self._categories: | |
| 150 # 'sched' is a high-volume tag, double the default buffer size | |
| 151 # to accommodate that | |
| 152 atrace_args.extend(['-b', '4096']) | |
| 153 extra_args = self._construct_extra_trace_command() | |
| 154 atrace_args.extend(extra_args) | |
| 155 | 170 |
| 156 tracer_args = util.construct_adb_shell_command( | 171 if ((self._options.trace_buf_size is not None) |
| 157 atrace_args, self._options.device_serial) | 172 and (self._options.trace_buf_size > 0)): |
| 173 atrace_args.extend(['-b', str(self._options.trace_buf_size)]) | |
| 174 elif 'sched' in self._categories: | |
| 175 # 'sched' is a high-volume tag, double the default buffer size | |
| 176 # to accommodate that | |
| 177 atrace_args.extend(['-b', '4096']) | |
| 178 extra_args = self._construct_extra_trace_args() | |
| 179 atrace_args.extend(extra_args) | |
| 158 | 180 |
| 159 return tracer_args | 181 return atrace_args |
| 182 | |
| 183 def _dump_trace(self): | |
| 184 """Dumps the atrace buffer and returns the dumped buffer.""" | |
| 185 dump_cmd = self._tracer_args + ['--async_dump'] | |
| 186 return self._device_utils.RunShellCommand(dump_cmd, split_lines=False) | |
| 187 | |
| 188 def _stop_trace(self): | |
| 189 """Stops the atrace trace. | |
| 190 | |
| 191 Tries to stop the atrace trace asynchronously and uses the fallback | |
| 192 method of running a zero-length synchronous trace if that fails. | |
| 193 """ | |
| 194 self._device_utils.RunShellCommand(self._tracer_args + ['--async_stop']) | |
| 195 cmd = ['cat', '/sys/kernel/debug/tracing/tracing_on'] | |
| 196 trace_on = int(self._device_utils.RunShellCommand(cmd)[0]) | |
| 197 if trace_on: | |
| 198 self._device_utils.RunShellCommand(self._tracer_args + ['-t 0']) | |
| 160 | 199 |
| 161 def _collect_trace_data(self): | 200 def _collect_trace_data(self): |
| 162 # Read the output from ADB in a worker thread. This allows us to monitor | 201 """Reads the output from atrace and stops the trace.""" |
| 163 # the progress of ADB and bail if ADB becomes unresponsive for any reason. | 202 result = self._dump_trace() |
| 164 | 203 data_start = re.search(TRACE_START_REGEXP, result).end(0) |
| 165 # Limit the stdout_queue to 128 entries because we will initially be reading | 204 output = re.sub(ADB_IGNORE_REGEXP, '', result[data_start:]) |
| 166 # one byte at a time. When the queue fills up, the reader thread will | 205 self._stop_trace() |
| 167 # block until there is room in the queue. Once we start downloading the | 206 return output |
| 168 # trace data, we will switch to reading data in larger chunks, and 128 | |
| 169 # entries should be plenty for that purpose. | |
| 170 stdout_queue = Queue.Queue(maxsize=128) | |
| 171 stderr_queue = Queue.Queue() | |
| 172 | |
| 173 if self._expect_trace: | |
| 174 # Use stdout.write() (here and for the rest of this function) instead | |
| 175 # of print() to avoid extra newlines. | |
| 176 sys.stdout.write('Capturing trace...') | |
| 177 | |
| 178 # Use a chunk_size of 1 for stdout so we can display the output to | |
| 179 # the user without waiting for a full line to be sent. | |
| 180 stdout_thread = FileReaderThread(self._adb.stdout, stdout_queue, | |
| 181 text_file=False, chunk_size=1) | |
| 182 stderr_thread = FileReaderThread(self._adb.stderr, stderr_queue, | |
| 183 text_file=True) | |
| 184 stdout_thread.start() | |
| 185 stderr_thread.start() | |
| 186 | |
| 187 # Holds the trace data returned by ADB. | |
| 188 trace_data = [] | |
| 189 # Keep track of the current line so we can find the TRACE_START_REGEXP. | |
| 190 current_line = '' | |
| 191 # Set to True once we've received the TRACE_START_REGEXP. | |
| 192 reading_trace_data = False | |
| 193 | |
| 194 last_status_update_time = time.time() | |
| 195 | |
| 196 while (stdout_thread.isAlive() or stderr_thread.isAlive() or | |
| 197 not stdout_queue.empty() or not stderr_queue.empty()): | |
| 198 if self._expect_trace: | |
| 199 last_status_update_time = status_update(last_status_update_time) | |
| 200 | |
| 201 while not stderr_queue.empty(): | |
| 202 # Pass along errors from adb. | |
| 203 line = stderr_queue.get() | |
| 204 sys.stderr.write(line) | |
| 205 | |
| 206 # Read stdout from adb. The loop exits if we don't get any data for | |
| 207 # ADB_STDOUT_READ_TIMEOUT seconds. | |
| 208 while True: | |
| 209 try: | |
| 210 chunk = stdout_queue.get(True, ADB_STDOUT_READ_TIMEOUT) | |
| 211 except Queue.Empty: | |
| 212 # Didn't get any data, so exit the loop to check that ADB is still | |
| 213 # alive and print anything sent to stderr. | |
| 214 break | |
| 215 | |
| 216 if reading_trace_data: | |
| 217 # Save, but don't print, the trace data. | |
| 218 trace_data.append(chunk) | |
| 219 else: | |
| 220 if not self._expect_trace: | |
| 221 sys.stdout.write(chunk) | |
| 222 else: | |
| 223 # Buffer the output from ADB so we can remove some strings that | |
| 224 # don't need to be shown to the user. | |
| 225 current_line += chunk | |
| 226 if re.match(TRACE_START_REGEXP, current_line): | |
| 227 # We are done capturing the trace. | |
| 228 sys.stdout.write('Done.\n') | |
| 229 # Now we start downloading the trace data. | |
| 230 sys.stdout.write('Downloading trace...') | |
| 231 | |
| 232 current_line = '' | |
| 233 # Use a larger chunk size for efficiency since we no longer | |
| 234 # need to worry about parsing the stream. | |
| 235 stdout_thread.set_chunk_size(4096) | |
| 236 reading_trace_data = True | |
| 237 elif chunk == '\n' or chunk == '\r': | |
| 238 # Remove ADB output that we don't care about. | |
| 239 current_line = re.sub(ADB_IGNORE_REGEXP, '', current_line) | |
| 240 if len(current_line) > 1: | |
| 241 # ADB printed something that we didn't understand, so show it | |
| 242 # it to the user (might be helpful for debugging). | |
| 243 sys.stdout.write(current_line) | |
| 244 # Reset our current line. | |
| 245 current_line = '' | |
| 246 | |
| 247 if self._expect_trace: | |
| 248 if reading_trace_data: | |
| 249 # Indicate to the user that the data download is complete. | |
| 250 sys.stdout.write('Done.\n') | |
| 251 else: | |
| 252 # We didn't receive the trace start tag, so something went wrong. | |
| 253 sys.stdout.write('ERROR.\n') | |
| 254 # Show any buffered ADB output to the user. | |
| 255 current_line = re.sub(ADB_IGNORE_REGEXP, '', current_line) | |
| 256 if current_line: | |
| 257 sys.stdout.write(current_line) | |
| 258 sys.stdout.write('\n') | |
| 259 | |
| 260 # The threads should already have stopped, so this is just for cleanup. | |
| 261 stdout_thread.join() | |
| 262 stderr_thread.join() | |
| 263 | |
| 264 self._adb.stdout.close() | |
| 265 self._adb.stderr.close() | |
| 266 | |
| 267 # The adb process should be done since it's io pipes are closed. Call | |
| 268 # poll() to set the returncode. | |
| 269 self._adb.poll() | |
| 270 | |
| 271 if self._adb.returncode != 0: | |
| 272 print >> sys.stderr, ('The command "%s" returned error code %d.' % | |
| 273 (' '.join(self._tracer_args), self._adb.returncode)) | |
| 274 sys.exit(1) | |
| 275 | |
| 276 return trace_data | |
| 277 | 207 |
| 278 def _preprocess_trace_data(self, trace_data): | 208 def _preprocess_trace_data(self, trace_data): |
| 279 """Performs various processing on atrace data. | 209 """Performs various processing on atrace data. |
| 280 | 210 |
| 281 Args: | 211 Args: |
| 282 trace_data: The raw trace data. | 212 trace_data: The raw trace data. |
| 283 Returns: | 213 Returns: |
| 284 The processed trace data. | 214 The processed trace data. |
| 285 """ | 215 """ |
| 286 trace_data = ''.join(trace_data) | |
| 287 if trace_data: | 216 if trace_data: |
| 288 trace_data = strip_and_decompress_trace(trace_data) | 217 trace_data = strip_and_decompress_trace(trace_data) |
| 289 | 218 |
| 290 if not trace_data: | 219 if not trace_data: |
| 291 print >> sys.stderr, ('No data was captured. Output file was not ' | 220 print >> sys.stderr, ('No data was captured. Output file was not ' |
| 292 'written.') | 221 'written.') |
| 293 sys.exit(1) | 222 sys.exit(1) |
| 294 | 223 |
| 295 if self._options.fix_threads: | 224 if self._options.fix_threads: |
| 296 # Issue ps command to device and patch thread names | 225 # Issue ps command to device and patch thread names |
| (...skipping 10 matching lines...) Expand all Loading... | |
| 307 if procfs_dump is not None: | 236 if procfs_dump is not None: |
| 308 pid2_tgid = extract_tgids(procfs_dump) | 237 pid2_tgid = extract_tgids(procfs_dump) |
| 309 trace_data = fix_missing_tgids(trace_data, pid2_tgid) | 238 trace_data = fix_missing_tgids(trace_data, pid2_tgid) |
| 310 | 239 |
| 311 if self._options.fix_circular: | 240 if self._options.fix_circular: |
| 312 trace_data = fix_circular_traces(trace_data) | 241 trace_data = fix_circular_traces(trace_data) |
| 313 | 242 |
| 314 return trace_data | 243 return trace_data |
| 315 | 244 |
| 316 | 245 |
| 317 class AtraceLegacyAgent(AtraceAgent): | |
| 318 | |
| 319 def _construct_list_categories_command(self): | |
| 320 LEGACY_CATEGORIES = """ sched - CPU Scheduling | |
| 321 freq - CPU Frequency | |
| 322 idle - CPU Idle | |
| 323 load - CPU Load | |
| 324 disk - Disk I/O (requires root) | |
| 325 bus - Bus utilization (requires root) | |
| 326 workqueue - Kernel workqueues (requires root)""" | |
| 327 return ["echo", LEGACY_CATEGORIES] | |
| 328 | |
| 329 def start(self): | |
| 330 super(AtraceLegacyAgent, self).start() | |
| 331 if self.expect_trace(): | |
| 332 SHELL_ARGS = ['getprop', 'debug.atrace.tags.enableflags'] | |
| 333 output, return_code = util.run_adb_shell(SHELL_ARGS, | |
| 334 self._options.device_serial) | |
| 335 if return_code != 0: | |
| 336 print >> sys.stderr, ( | |
| 337 '\nThe command "%s" failed with the following message:' | |
| 338 % ' '.join(SHELL_ARGS)) | |
| 339 print >> sys.stderr, str(output) | |
| 340 sys.exit(1) | |
| 341 | |
| 342 flags = 0 | |
| 343 try: | |
| 344 if output.startswith('0x'): | |
| 345 flags = int(output, 16) | |
| 346 elif output.startswith('0'): | |
| 347 flags = int(output, 8) | |
| 348 else: | |
| 349 flags = int(output) | |
| 350 except ValueError: | |
| 351 pass | |
| 352 | |
| 353 if flags: | |
| 354 tags = [] | |
| 355 for desc, bit in LEGACY_TRACE_TAG_BITS: | |
| 356 if bit & flags: | |
| 357 tags.append(desc) | |
| 358 categories = tags + self._categories | |
| 359 print 'Collecting data with following categories:', ' '.join(categories) | |
| 360 | |
| 361 def _construct_extra_trace_command(self): | |
| 362 extra_args = [] | |
| 363 if not self._categories: | |
| 364 self._categories = ['sched', ] | |
| 365 if 'sched' in self._categories: | |
| 366 extra_args.append('-s') | |
| 367 if 'freq' in self._categories: | |
| 368 extra_args.append('-f') | |
| 369 if 'idle' in self._categories: | |
| 370 extra_args.append('-i') | |
| 371 if 'load' in self._categories: | |
| 372 extra_args.append('-l') | |
| 373 if 'disk' in self._categories: | |
| 374 extra_args.append('-d') | |
| 375 if 'bus' in self._categories: | |
| 376 extra_args.append('-u') | |
| 377 if 'workqueue' in self._categories: | |
| 378 extra_args.append('-w') | |
| 379 | |
| 380 return extra_args | |
| 381 | |
| 382 | |
| 383 class BootAgent(AtraceAgent): | |
| 384 """AtraceAgent that specializes in tracing the boot sequence.""" | |
| 385 | |
| 386 def __init__(self, options, categories): | |
| 387 super(BootAgent, self).__init__(options, categories) | |
| 388 | |
| 389 def start(self): | |
| 390 try: | |
| 391 setup_args = self._construct_setup_command() | |
| 392 try: | |
| 393 subprocess.check_call(setup_args) | |
| 394 print 'Hit Ctrl+C once the device has booted up.' | |
| 395 while True: | |
| 396 time.sleep(1) | |
| 397 except KeyboardInterrupt: | |
| 398 pass | |
| 399 tracer_args = self._construct_trace_command() | |
| 400 self._adb = subprocess.Popen(tracer_args, stdout=subprocess.PIPE, | |
| 401 stderr=subprocess.PIPE) | |
| 402 except OSError as error: | |
| 403 print >> sys.stderr, ( | |
| 404 'The command "%s" failed with the following error:' % | |
| 405 ' '.join(tracer_args)) | |
| 406 print >> sys.stderr, ' ', error | |
| 407 sys.exit(1) | |
| 408 | |
| 409 def _construct_setup_command(self): | |
| 410 echo_args = ['echo'] + self._categories + ['>', BOOTTRACE_CATEGORIES] | |
| 411 setprop_args = ['setprop', BOOTTRACE_PROP, '1'] | |
| 412 reboot_args = ['reboot'] | |
| 413 return util.construct_adb_shell_command( | |
| 414 echo_args + ['&&'] + setprop_args + ['&&'] + reboot_args, | |
| 415 self._options.device_serial) | |
| 416 | |
| 417 def _construct_trace_command(self): | |
| 418 self._expect_trace = True | |
| 419 atrace_args = ['atrace', '--async_stop'] | |
| 420 setprop_args = ['setprop', BOOTTRACE_PROP, '0'] | |
| 421 rm_args = ['rm', BOOTTRACE_CATEGORIES] | |
| 422 return util.construct_adb_shell_command( | |
| 423 atrace_args + ['&&'] + setprop_args + ['&&'] + rm_args, | |
| 424 self._options.device_serial) | |
| 425 | |
| 426 | |
| 427 class FileReaderThread(threading.Thread): | |
| 428 """Reads data from a file/pipe on a worker thread. | |
| 429 | |
| 430 Use the standard threading. Thread object API to start and interact with the | |
| 431 thread (start(), join(), etc.). | |
| 432 """ | |
| 433 | |
| 434 def __init__(self, file_object, output_queue, text_file, chunk_size=-1): | |
| 435 """Initializes a FileReaderThread. | |
| 436 | |
| 437 Args: | |
| 438 file_object: The file or pipe to read from. | |
| 439 output_queue: A Queue.Queue object that will receive the data | |
| 440 text_file: If True, the file will be read one line at a time, and | |
| 441 chunk_size will be ignored. If False, line breaks are ignored and | |
| 442 chunk_size must be set to a positive integer. | |
| 443 chunk_size: When processing a non-text file (text_file = False), | |
| 444 chunk_size is the amount of data to copy into the queue with each | |
| 445 read operation. For text files, this parameter is ignored. | |
| 446 """ | |
| 447 threading.Thread.__init__(self) | |
| 448 self._file_object = file_object | |
| 449 self._output_queue = output_queue | |
| 450 self._text_file = text_file | |
| 451 self._chunk_size = chunk_size | |
| 452 assert text_file or chunk_size > 0 | |
| 453 | |
| 454 def run(self): | |
| 455 """Overrides Thread's run() function. | |
| 456 | |
| 457 Returns when an EOF is encountered. | |
| 458 """ | |
| 459 if self._text_file: | |
| 460 # Read a text file one line at a time. | |
| 461 for line in self._file_object: | |
| 462 self._output_queue.put(line) | |
| 463 else: | |
| 464 # Read binary or text data until we get to EOF. | |
| 465 while True: | |
| 466 chunk = self._file_object.read(self._chunk_size) | |
| 467 if not chunk: | |
| 468 break | |
| 469 self._output_queue.put(chunk) | |
| 470 | |
| 471 def set_chunk_size(self, chunk_size): | |
| 472 """Change the read chunk size. | |
| 473 | |
| 474 This function can only be called if the FileReaderThread object was | |
| 475 created with an initial chunk_size > 0. | |
| 476 Args: | |
| 477 chunk_size: the new chunk size for this file. Must be > 0. | |
| 478 """ | |
| 479 # The chunk size can be changed asynchronously while a file is being read | |
| 480 # in a worker thread. However, type of file can not be changed after the | |
| 481 # the FileReaderThread has been created. These asserts verify that we are | |
| 482 # only changing the chunk size, and not the type of file. | |
| 483 assert not self._text_file | |
| 484 assert chunk_size > 0 | |
| 485 self._chunk_size = chunk_size | |
| 486 | |
| 487 | |
| 488 def get_default_categories(device_serial): | 246 def get_default_categories(device_serial): |
| 247 """Gets the list of atrace categories available for tracing.""" | |
| 489 categories_output, return_code = util.run_adb_shell(LIST_CATEGORIES_ARGS, | 248 categories_output, return_code = util.run_adb_shell(LIST_CATEGORIES_ARGS, |
| 490 device_serial) | 249 device_serial) |
| 491 | 250 |
| 492 if return_code == 0 and categories_output: | 251 if return_code == 0 and categories_output: |
| 493 categories = [c.split('-')[0].strip() | 252 categories = [c.split('-')[0].strip() |
| 494 for c in categories_output.splitlines()] | 253 for c in categories_output.splitlines()] |
| 495 return [c for c in categories if c in DEFAULT_CATEGORIES] | 254 return [c for c in categories if c in DEFAULT_CATEGORIES] |
| 496 | 255 |
| 497 return [] | 256 return [] |
| 498 | 257 |
| 499 | 258 |
| 500 def status_update(last_update_time): | |
| 501 current_time = time.time() | |
| 502 if (current_time - last_update_time) >= MIN_TIME_BETWEEN_STATUS_UPDATES: | |
| 503 # Gathering a trace may take a while. Keep printing something so users | |
| 504 # don't think the script has hung. | |
| 505 sys.stdout.write('.') | |
| 506 sys.stdout.flush() | |
| 507 return current_time | |
| 508 | |
| 509 return last_update_time | |
| 510 | |
| 511 | |
| 512 def extract_thread_list(trace_text): | 259 def extract_thread_list(trace_text): |
| 513 """Removes the thread list from the given trace data. | 260 """Removes the thread list from the given trace data. |
| 261 | |
| 514 Args: | 262 Args: |
| 515 trace_text: The text portion of the trace | 263 trace_text: The text portion of the trace |
| 516 Returns: | 264 Returns: |
| 517 a map of thread ids to thread names | 265 a map of thread ids to thread names |
| 518 """ | 266 """ |
| 519 | 267 |
| 520 threads = {} | 268 threads = {} |
| 521 # start at line 1 to skip the top of the ps dump: | 269 # start at line 1 to skip the top of the ps dump: |
| 522 text = trace_text.splitlines() | 270 text = trace_text.splitlines() |
| 523 for line in text[1:]: | 271 for line in text[1:]: |
| 524 cols = line.split(None, 8) | 272 cols = line.split(None, 8) |
| 525 if len(cols) == 9: | 273 if len(cols) == 9: |
| 526 tid = int(cols[1]) | 274 tid = int(cols[1]) |
| 527 name = cols[8] | 275 name = cols[8] |
| 528 threads[tid] = name | 276 threads[tid] = name |
| 529 | 277 |
| 530 return threads | 278 return threads |
| 531 | 279 |
| 532 | 280 |
| 533 def extract_tgids(trace_text): | 281 def extract_tgids(trace_text): |
| 534 """Removes the procfs dump from the given trace text | 282 """Removes the procfs dump from the given trace text |
| 283 | |
| 535 Args: | 284 Args: |
| 536 trace_text: The text portion of the trace | 285 trace_text: The text portion of the trace |
| 537 Returns: | 286 Returns: |
| 538 a map of pids to their tgid. | 287 a map of pids to their tgid. |
| 539 """ | 288 """ |
| 540 tgid_2pid = {} | 289 tgid_2pid = {} |
| 541 text = trace_text.splitlines() | 290 text = trace_text.splitlines() |
| 542 for line in text: | 291 for line in text: |
| 543 result = re.match('^/proc/([0-9]+)/task/([0-9]+)', line) | 292 result = re.match('^/proc/([0-9]+)/task/([0-9]+)', line) |
| 544 if result: | 293 if result: |
| (...skipping 12 matching lines...) Expand all Loading... | |
| 557 The decompressed trace data. | 306 The decompressed trace data. |
| 558 """ | 307 """ |
| 559 # Collapse CRLFs that are added by adb shell. | 308 # Collapse CRLFs that are added by adb shell. |
| 560 if trace_data.startswith('\r\n'): | 309 if trace_data.startswith('\r\n'): |
| 561 trace_data = trace_data.replace('\r\n', '\n') | 310 trace_data = trace_data.replace('\r\n', '\n') |
| 562 elif trace_data.startswith('\r\r\n'): | 311 elif trace_data.startswith('\r\r\n'): |
| 563 # On windows, adb adds an extra '\r' character for each line. | 312 # On windows, adb adds an extra '\r' character for each line. |
| 564 trace_data = trace_data.replace('\r\r\n', '\n') | 313 trace_data = trace_data.replace('\r\r\n', '\n') |
| 565 | 314 |
| 566 # Skip the initial newline. | 315 # Skip the initial newline. |
| 567 trace_data = trace_data[1:] | 316 if trace_data[0] == '\n': |
| 317 trace_data = trace_data[1:] | |
| 568 | 318 |
| 569 if not trace_data.startswith(TRACE_TEXT_HEADER): | 319 if not trace_data.startswith(TRACE_TEXT_HEADER): |
| 570 # No header found, so assume the data is compressed. | 320 # No header found, so assume the data is compressed. |
| 571 trace_data = zlib.decompress(trace_data) | 321 trace_data = zlib.decompress(trace_data) |
| 572 | 322 |
| 573 # Enforce Unix line-endings. | 323 # Enforce Unix line-endings. |
| 574 trace_data = trace_data.replace('\r', '') | 324 trace_data = trace_data.replace('\r', '') |
| 575 | 325 |
| 576 # Skip any initial newlines. | 326 # Skip any initial newlines. |
| 577 while trace_data and trace_data[0] == '\n': | 327 while trace_data and trace_data[0] == '\n': |
| (...skipping 27 matching lines...) Expand all Loading... | |
| 605 | 355 |
| 606 # matches something like: | 356 # matches something like: |
| 607 # Binder_2-895, or com.google.android.inputmethod.latin-1078 etc... | 357 # Binder_2-895, or com.google.android.inputmethod.latin-1078 etc... |
| 608 trace_data = re.sub(r'^\s*(\S+)-(\d+)', repl, trace_data, | 358 trace_data = re.sub(r'^\s*(\S+)-(\d+)', repl, trace_data, |
| 609 flags=re.MULTILINE) | 359 flags=re.MULTILINE) |
| 610 return trace_data | 360 return trace_data |
| 611 | 361 |
| 612 | 362 |
| 613 def fix_missing_tgids(trace_data, pid2_tgid): | 363 def fix_missing_tgids(trace_data, pid2_tgid): |
| 614 """Replaces missing TGIDs from the trace data with those found in procfs | 364 """Replaces missing TGIDs from the trace data with those found in procfs |
| 365 | |
| 615 Args: | 366 Args: |
| 616 trace_data: the atrace data | 367 trace_data: the atrace data |
| 617 Returns: | 368 Returns: |
| 618 The updated trace data with missing TGIDs replaced with the correct TGID | 369 The updated trace data with missing TGIDs replaced with the correct TGID |
| 619 """ | 370 """ |
| 620 | 371 |
| 621 def repl(m): | 372 def repl(m): |
| 622 tid = m.group(2) | 373 tid = m.group(2) |
| 623 if (int(tid) > 0 and m.group(1) != '<idle>' and m.group(3) == '(-----)' | 374 if (int(tid) > 0 and m.group(1) != '<idle>' and m.group(3) == '(-----)' |
| 624 and tid in pid2_tgid): | 375 and tid in pid2_tgid): |
| 625 # returns Proc_name-PID (TGID) | 376 # returns Proc_name-PID (TGID) |
| 626 # Binder_2-381 (-----) becomes Binder_2-381 (128) | 377 # Binder_2-381 (-----) becomes Binder_2-381 (128) |
| 627 return m.group(1) + '-' + m.group(2) + ' ( ' + pid2_tgid[tid] + ')' | 378 return m.group(1) + '-' + m.group(2) + ' ( ' + pid2_tgid[tid] + ')' |
| 628 | 379 |
| 629 return m.group(0) | 380 return m.group(0) |
| 630 | 381 |
| 631 # matches something like: | 382 # matches something like: |
| 632 # Binder_2-895 (-----) | 383 # Binder_2-895 (-----) |
| 633 trace_data = re.sub(r'^\s*(\S+)-(\d+)\s+(\(\S+\))', repl, trace_data, | 384 trace_data = re.sub(r'^\s*(\S+)-(\d+)\s+(\(\S+\))', repl, trace_data, |
| 634 flags=re.MULTILINE) | 385 flags=re.MULTILINE) |
| 635 return trace_data | 386 return trace_data |
| 636 | 387 |
| 637 | 388 |
| 638 def fix_circular_traces(out): | 389 def fix_circular_traces(out): |
| 639 """Fix inconsistentcies in traces due to circular buffering. | 390 """Fix inconsistencies in traces due to circular buffering. |
| 640 | 391 |
| 641 The circular buffers are kept per CPU, so it is not guaranteed that the | 392 The circular buffers are kept per CPU, so it is not guaranteed that the |
| 642 beginning of a slice is overwritten before the end. To work around this, we | 393 beginning of a slice is overwritten before the end. To work around this, we |
| 643 throw away the prefix of the trace where not all CPUs have events yet. | 394 throw away the prefix of the trace where not all CPUs have events yet. |
| 644 | 395 |
| 645 Args: | 396 Args: |
| 646 out: The data to fix. | 397 out: The data to fix. |
| 647 Returns: | 398 Returns: |
| 648 The updated trace data. | 399 The updated trace data. |
| 649 """ | 400 """ |
| (...skipping 14 matching lines...) Expand all Loading... | |
| 664 start_of_full_trace = result.start() | 415 start_of_full_trace = result.start() |
| 665 else: | 416 else: |
| 666 break | 417 break |
| 667 | 418 |
| 668 if start_of_full_trace > 0: | 419 if start_of_full_trace > 0: |
| 669 # Need to keep the header intact to make the importer happy. | 420 # Need to keep the header intact to make the importer happy. |
| 670 end_of_header = re.search(r'^[^#]', out, re.MULTILINE).start() | 421 end_of_header = re.search(r'^[^#]', out, re.MULTILINE).start() |
| 671 out = out[:end_of_header] + out[start_of_full_trace:] | 422 out = out[:end_of_header] + out[start_of_full_trace:] |
| 672 return out | 423 return out |
| 673 | 424 |
| 425 def do_preprocess_adb_cmd(command, serial): | |
| 426 """Run an ADB command for preprocessing of output. | |
| 674 | 427 |
| 675 def do_popen(args): | 428 Run an ADB command and get the result. This function is used |
| 676 try: | 429 for running commands relating to preprocessing of output data. |
| 677 adb = subprocess.Popen(args, stdout=subprocess.PIPE, | |
| 678 stderr=subprocess.PIPE) | |
| 679 except OSError as error: | |
| 680 print >> sys.stderr, ( | |
| 681 'The command "%s" failed with the following error:' % | |
| 682 ' '.join(args)) | |
| 683 print >> sys.stderr, ' ', error | |
| 684 sys.exit(1) | |
| 685 | 430 |
| 686 return adb | 431 Args: |
| 687 | 432 command: Command to run. |
| 688 | 433 serial: Serial number of device. |
| 689 def do_preprocess_adb_cmd(command, serial): | 434 """ |
| 690 args = [command] | 435 args = [command] |
| 691 dump, ret_code = util.run_adb_shell(args, serial) | 436 dump, ret_code = util.run_adb_shell(args, serial) |
| 692 if ret_code != 0: | 437 if ret_code != 0: |
| 693 return None | 438 return None |
| 694 | 439 |
| 695 dump = ''.join(dump) | 440 dump = ''.join(dump) |
| 696 return dump | 441 return dump |
| 442 | |
| 443 | |
| 444 class BootAgent(AtraceAgent): | |
| 445 """AtraceAgent that specializes in tracing the boot sequence.""" | |
| 446 | |
| 447 def __init__(self, options, categories): | |
| 448 super(BootAgent, self).__init__(options, categories) | |
| 449 | |
| 450 def StartAgentTracing(self): | |
| 451 try: | |
| 452 setup_args = self._construct_setup_command() | |
| 453 subprocess.check_call(setup_args) | |
| 454 except OSError as error: | |
| 455 print >> sys.stderr, ( | |
| 456 'The command "%s" failed with the following error:' % | |
| 457 ' '.join(setup_args)) | |
| 458 print >> sys.stderr, ' ', error | |
| 459 sys.exit(1) | |
| 460 | |
| 461 def _dump_trace(self): #called by StopAgentTracing | |
| 462 """Dumps the running trace asynchronously and returns the dumped trace.""" | |
| 463 dump_cmd = get_boot_dump_cmd() | |
| 464 return self._device_utils.RunShellCommand(dump_cmd, split_lines=False) | |
| 465 | |
| 466 def _stop_trace(self): # called by _collect_trace_data via StopAgentTracing | |
| 467 pass # don't need to stop separately; already done in dump_trace | |
| 468 | |
| 469 def _construct_setup_command(self): | |
| 470 """Constructs the command that is used to start up the boot trace.""" | |
| 471 echo_args = ['echo'] + self._categories + ['>', BOOTTRACE_CATEGORIES] | |
| 472 setprop_args = ['setprop', BOOTTRACE_PROP, '1'] | |
| 473 reboot_args = ['reboot'] | |
| 474 return util.construct_adb_shell_command( | |
| 475 echo_args + ['&&'] + setprop_args + ['&&'] + reboot_args, | |
| 476 self._options.device_serial) | |
| 477 | |
| 478 def get_boot_dump_cmd(): | |
| 479 """Constructs the command that is used to dump the boot trace.""" | |
| 480 return ['atrace', '--async_stop', '&&', | |
| 481 'setprop', BOOTTRACE_PROP, '0', '&&', | |
| 482 'rm', BOOTTRACE_CATEGORIES] | |
| OLD | NEW |