1#!/usr/bin/python3 2 3# Copyright (C) 2016 The Android Open Source Project 4# 5# Licensed under the Apache License, Version 2.0 (the "License"); 6# you may not use this file except in compliance with the License. 7# You may obtain a copy of the License at 8# 9# http://www.apache.org/licenses/LICENSE-2.0 10# 11# Unless required by applicable law or agreed to in writing, software 12# distributed under the License is distributed on an "AS IS" BASIS, 13# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 14# See the License for the specific language governing permissions and 15# limitations under the License. 16# 17"""Tool to analyze logcat and dmesg logs. 18 19bootanalyze read logcat and dmesg logs and determines key points for boot. 20""" 21 22import argparse 23import collections 24import datetime 25import math 26import operator 27import os 28import re 29import select 30import subprocess 31import time 32import threading 33import yaml 34 35from datetime import datetime 36 37TIME_DMESG = r"\[\s*(\d+\.\d+)\]" 38TIME_LOGCAT = r"[0-9]+\.?[0-9]*" 39KERNEL_TIME_KEY = "kernel" 40BOOT_ANIM_END_TIME_KEY = "BootAnimEnd" 41KERNEL_BOOT_COMPLETE = "BootComplete_kernel" 42LOGCAT_BOOT_COMPLETE = "BootComplete" 43CARWATCHDOG_BOOT_COMPLETE = "CarWatchdogBootupProfilingComplete" 44LAUNCHER_START = "LauncherStart" 45CARWATCHDOG_DUMP_COMMAND = "adb shell dumpsys android.automotive.watchdog.ICarWatchdog/default" 46BOOT_TIME_TOO_BIG = 200.0 47MAX_RETRIES = 5 48DEBUG = False 49DEBUG_PATTERN = False 50ADB_CMD = "adb" 51TIMING_THRESHOLD = 5.0 52BOOT_PROP = r"\[ro\.boottime\.([^\]]+)\]:\s+\[(\d+)\]" 53BOOTLOADER_TIME_PROP = r"\[ro\.boot\.boottime\]:\s+\[([^\]]+)\]" 54CARWATCHDOG_PARSER_CMD = 'perf_stats_parser' 55 56max_wait_time = BOOT_TIME_TOO_BIG 57 58def main(): 59 global ADB_CMD 60 61 args = init_arguments() 62 63 if args.iterate < 1: 64 raise Exception('Number of iteration must be >=1') 65 66 if args.iterate > 1 and not args.reboot: 67 print("Forcing reboot flag") 68 args.reboot = True 69 70 if args.serial: 71 ADB_CMD = "%s %s" % ("adb -s", args.serial) 72 73 error_time = BOOT_TIME_TOO_BIG * 10 74 if args.errortime: 75 error_time = float(args.errortime) 76 if args.maxwaittime: 77 global max_wait_time 78 max_wait_time = float(args.maxwaittime) 79 80 components_to_monitor = {} 81 if args.componentmonitor: 82 items = args.componentmonitor.split(",") 83 for item in items: 84 kv = item.split("=") 85 key = kv[0] 86 value = float(kv[1]) 87 components_to_monitor[key] = value 88 89 cfg = yaml.load(args.config, Loader=yaml.SafeLoader) 90 91 if args.stressfs: 92 if run_adb_cmd('install -r -g ' + args.stressfs) != 0: 93 raise Exception('StressFS APK not installed') 94 95 if args.iterate > 1 and args.bootchart: 96 run_adb_shell_cmd_as_root('touch /data/bootchart/enabled') 97 98 search_events_pattern = {key: re.compile(pattern) 99 for key, pattern in cfg['events'].items()} 100 timing_events_pattern = {key: re.compile(pattern) 101 for key, pattern in cfg['timings'].items()} 102 shutdown_events_pattern = {key: re.compile(pattern) 103 for key, pattern in cfg['shutdown_events'].items()} 104 if DEBUG_PATTERN: 105 print("search event:{} timing event:{}".format(search_events_pattern, timing_events_pattern)) 106 107 now = datetime.now().strftime("%Y-%m-%d-%H-%M-%S") 108 boot_chart_file_path_prefix = "bootchart-" + now 109 systrace_file_path_prefix = "systrace-" + now 110 111 if args.output: 112 boot_chart_file_path_prefix = args.output + '/' + boot_chart_file_path_prefix 113 systrace_file_path_prefix = args.output + '/' + systrace_file_path_prefix 114 115 data_points = {} 116 kernel_timing_points = collections.OrderedDict() 117 logcat_timing_points = collections.OrderedDict() 118 boottime_points = collections.OrderedDict() 119 shutdown_event_all = collections.OrderedDict() 120 shutdown_timing_event_all = collections.OrderedDict() 121 for it in range(0, args.iterate): 122 if args.iterate > 1: 123 print("Run: {0}".format(it)) 124 attempt = 1 125 processing_data = None 126 timings = None 127 boottime_events = None 128 while attempt <= MAX_RETRIES and processing_data is None: 129 attempt += 1 130 processing_data, kernel_timings, logcat_timings, boottime_events, shutdown_events,\ 131 shutdown_timing_events = iterate(\ 132 args, search_events_pattern, timing_events_pattern, shutdown_events_pattern, cfg,\ 133 error_time, components_to_monitor) 134 if shutdown_events: 135 for k, v in shutdown_events.items(): 136 events = shutdown_event_all.get(k) 137 if not events: 138 events = [] 139 shutdown_event_all[k] = events 140 events.append(v) 141 if shutdown_timing_events: 142 for k, v in shutdown_timing_events.items(): 143 events = shutdown_timing_event_all.get(k) 144 if not events: 145 events = [] 146 shutdown_timing_event_all[k] = events 147 events.append(v) 148 if not processing_data or not boottime_events: 149 # Processing error 150 print("Failed to collect valid samples for run {0}".format(it)) 151 continue 152 153 if args.bootchart: 154 grab_bootchart(boot_chart_file_path_prefix + "_run_" + str(it)) 155 156 if args.systrace: 157 grab_systrace(systrace_file_path_prefix + "_run_" + str(it)) 158 159 if args.carwatchdog: 160 grab_carwatchdog_bootstats(args.output) 161 162 for k, v in processing_data.items(): 163 if k not in data_points: 164 data_points[k] = [] 165 data_points[k].append(v['value']) 166 167 if kernel_timings is not None: 168 for k, v in kernel_timings.items(): 169 if k not in kernel_timing_points: 170 kernel_timing_points[k] = [] 171 kernel_timing_points[k].append(v) 172 if logcat_timings is not None: 173 for k, v in logcat_timings.items(): 174 if k not in logcat_timing_points: 175 logcat_timing_points[k] = [] 176 logcat_timing_points[k].append(v) 177 178 for k, v in boottime_events.items(): 179 if k not in boottime_points: 180 boottime_points[k] = [] 181 boottime_points[k].append(v) 182 183 if args.stressfs: 184 run_adb_cmd('uninstall com.android.car.test.stressfs') 185 run_adb_shell_cmd('"rm -rf /storage/emulated/0/stressfs_data*"') 186 187 if args.iterate > 1: 188 print("-----------------") 189 print("\nshutdown events after {0} runs".format(args.iterate)) 190 print('{0:30}: {1:<7} {2:<7} {3}'.format("Event", "Mean", "stddev", "#runs")) 191 for item in list(shutdown_event_all.items()): 192 num_runs = len(item[1]) 193 print('{0:30}: {1:<7.5} {2:<7.5} {3} {4}'.format( 194 item[0], sum(item[1])/num_runs, stddev(item[1]),\ 195 "*time taken" if item[0].startswith("init.") else "",\ 196 num_runs if num_runs != args.iterate else "")) 197 print("\nshutdown timing events after {0} runs".format(args.iterate)) 198 print('{0:30}: {1:<7} {2:<7} {3}'.format("Event", "Mean", "stddev", "#runs")) 199 for item in list(shutdown_timing_event_all.items()): 200 num_runs = len(item[1]) 201 print('{0:30}: {1:<7.5} {2:<7.5} {3} {4}'.format( 202 item[0], sum(item[1])/num_runs, stddev(item[1]),\ 203 "*time taken" if item[0].startswith("init.") else "",\ 204 num_runs if num_runs != args.iterate else "")) 205 206 print("-----------------") 207 print("ro.boottime.* after {0} runs".format(args.iterate)) 208 print('{0:30}: {1:<7} {2:<7} {3}'.format("Event", "Mean", "stddev", "#runs")) 209 for item in list(boottime_points.items()): 210 num_runs = len(item[1]) 211 print('{0:30}: {1:<7.5} {2:<7.5} {3} {4}'.format( 212 item[0], sum(item[1])/num_runs, stddev(item[1]),\ 213 "*time taken" if item[0].startswith("init.") else "",\ 214 num_runs if num_runs != args.iterate else "")) 215 216 if args.timings: 217 dump_timings_points_summary("Kernel", kernel_timing_points, args) 218 dump_timings_points_summary("Logcat", logcat_timing_points, args) 219 220 221 print("-----------------") 222 print("Avg values after {0} runs".format(args.iterate)) 223 print('{0:30}: {1:<7} {2:<7} {3}'.format("Event", "Mean", "stddev", "#runs")) 224 225 average_with_stddev = [] 226 for item in list(data_points.items()): 227 average_with_stddev.append((item[0], sum(item[1])/len(item[1]), stddev(item[1]),\ 228 len(item[1]))) 229 for item in sorted(average_with_stddev, key=lambda entry: entry[1]): 230 print('{0:30}: {1:<7.5} {2:<7.5} {3}'.format( 231 item[0], item[1], item[2], item[3] if item[3] != args.iterate else "")) 232 233 run_adb_shell_cmd_as_root('rm /data/bootchart/enabled') 234 235 236def dump_timings_points_summary(msg_header, timing_points, args): 237 averaged_timing_points = [] 238 for item in list(timing_points.items()): 239 average = sum(item[1])/len(item[1]) 240 std_dev = stddev(item[1]) 241 averaged_timing_points.append((item[0], average, std_dev, len(item[1]))) 242 243 print("-----------------") 244 print(msg_header + " timing in order, Avg time values after {0} runs".format(args.iterate)) 245 print('{0:30}: {1:<7} {2:<7} {3}'.format("Event", "Mean", "stddev", "#runs")) 246 for item in averaged_timing_points: 247 print('{0:30}: {1:<7.5} {2:<7.5} {3}'.format( 248 item[0], item[1], item[2], item[3] if item[3] != args.iterate else "")) 249 250 print("-----------------") 251 print(msg_header + " timing top items, Avg time values after {0} runs".format(args.iterate)) 252 print('{0:30}: {1:<7} {2:<7} {3}'.format("Event", "Mean", "stddev", "#runs")) 253 for item in sorted(averaged_timing_points, key=lambda entry: entry[1], reverse=True): 254 if item[1] < TIMING_THRESHOLD: 255 break 256 print('{0:30}: {1:<7.5} {2:<7.5} {3}'.format( 257 item[0], item[1], item[2], item[3] if item[3] != args.iterate else "")) 258 259def capture_bugreport(bugreport_hint, boot_complete_time): 260 now = datetime.now() 261 bugreport_file = ("bugreport-%s-" + bugreport_hint + "-%s.zip") \ 262 % (now.strftime("%Y-%m-%d-%H-%M-%S"), str(boot_complete_time)) 263 print("Boot up time too big, will capture bugreport %s" % (bugreport_file)) 264 os.system(ADB_CMD + " bugreport " + bugreport_file) 265 266def generate_timing_points(timing_events, timings): 267 timing_points = collections.OrderedDict() 268 monitor_contention_points = collections.OrderedDict() 269 for k, l in timing_events.items(): 270 for v in l: 271 name, time_v = extract_timing(v, timings) 272 if name and time_v: 273 if v.find("SystemServerTimingAsync") > 0: 274 name = "(" + name + ")" 275 if k.endswith("_secs"): 276 time_v = time_v * 1000.0 277 if k.startswith("long_monitor_contention"): 278 monitor_contention_points[v] = time_v 279 continue 280 new_name = name 281 name_index = 0 282 while timing_points.get(new_name): # if the name is already taken, append #digit 283 name_index += 1 284 new_name = name + "#" + str(name_index) 285 timing_points[new_name] = time_v 286 return timing_points, monitor_contention_points 287 288def dump_timing_points(msg_header, timing_points): 289 print(msg_header + " event timing in time order, key: time") 290 for item in list(timing_points.items()): 291 print('{0:30}: {1:<7.5}'.format(item[0], item[1])) 292 print("-----------------") 293 print(msg_header + " event timing top items") 294 for item in sorted(list(timing_points.items()), key=operator.itemgetter(1), reverse=True): 295 if item[1] < TIMING_THRESHOLD: 296 break 297 print('{0:30}: {1:<7.5}'.format( 298 item[0], item[1])) 299 print("-----------------") 300 301def dump_monitor_contentions(logcat_monitor_contentions): 302 print("Monitor contentions over 100ms:") 303 for item in list(logcat_monitor_contentions.items()): 304 if item[1] > 100: 305 print('{0:<7.5}ms: {1}'.format(item[1], item[0])) 306 print("-----------------") 307 308def handle_reboot_log(capture_log_on_error, shutdown_events_pattern, components_to_monitor): 309 shutdown_events, shutdown_timing_events = collect_logcat_for_shutdown(capture_log_on_error,\ 310 shutdown_events_pattern, components_to_monitor) 311 print("\nshutdown events: time") 312 for item in list(shutdown_events.items()): 313 print('{0:30}: {1:<7.5}'.format(item[0], item[1])) 314 print("\nshutdown timing events: time") 315 for item in list(shutdown_timing_events.items()): 316 print('{0:30}: {1:<7.5}'.format(item[0], item[1])) 317 return shutdown_events, shutdown_timing_events 318 319def collect_dmesg_events(search_events_pattern, timings_pattern, results): 320 dmesg_events, kernel_timing_events = collect_events(search_events_pattern, ADB_CMD +\ 321 ' shell su root dmesg -w', timings_pattern,\ 322 [KERNEL_BOOT_COMPLETE], True) 323 results.append(dmesg_events) 324 results.append(kernel_timing_events) 325 326def iterate(args, search_events_pattern, timings_pattern, shutdown_events_pattern, cfg, error_time,\ 327 components_to_monitor): 328 shutdown_events = None 329 shutdown_timing_events = None 330 if args.reboot: 331 # sleep to make sure that logcat reader is reading before adb is gone by reboot. ugly but make 332 # impl simple. 333 t = threading.Thread(target=lambda: (time.sleep(2), reboot(args.serial, args.stressfs != '',\ 334 args.permissive, args.adb_reboot, args.buffersize))) 335 t.start() 336 shutdown_events, shutdown_timing_events = handle_reboot_log(True, shutdown_events_pattern,\ 337 components_to_monitor) 338 t.join() 339 340 results = [] 341 t = threading.Thread(target=collect_dmesg_events, args=(search_events_pattern,\ 342 timings_pattern, results)) 343 t.start() 344 345 logcat_stop_events = [LOGCAT_BOOT_COMPLETE, LAUNCHER_START] 346 if args.fs_check: 347 logcat_stop_events.append("FsStat") 348 if args.carwatchdog: 349 logcat_stop_events.append(CARWATCHDOG_BOOT_COMPLETE) 350 logcat_events, logcat_timing_events = collect_events( 351 search_events_pattern, ADB_CMD + ' logcat -b all -v epoch', timings_pattern,\ 352 logcat_stop_events, False) 353 354 t.join() 355 dmesg_events = results[0] 356 kernel_timing_events = results[1] 357 358 logcat_event_time = extract_time(logcat_events, TIME_LOGCAT, float) 359 logcat_original_time = extract_time(logcat_events, TIME_LOGCAT, str); 360 dmesg_event_time = extract_time(dmesg_events, TIME_DMESG, float); 361 boottime_events = fetch_boottime_property() 362 events = {} 363 events_to_correct = [] 364 replaced_from_dmesg = set() 365 366 time_correction_delta = 0 367 time_correction_time = 0 368 if ('time_correction_key' in cfg 369 and cfg['time_correction_key'] in logcat_events): 370 match = search_events_pattern[cfg['time_correction_key']].search( 371 logcat_events[cfg['time_correction_key']]) 372 if match and logcat_event_time[cfg['time_correction_key']]: 373 time_correction_delta = float(match.group(1)) 374 time_correction_time = logcat_event_time[cfg['time_correction_key']] 375 376 debug("time_correction_delta = {0}, time_correction_time = {1}".format( 377 time_correction_delta, time_correction_time)) 378 379 for k, v in logcat_event_time.items(): 380 if v <= time_correction_time: 381 logcat_event_time[k] += time_correction_delta 382 v = v + time_correction_delta 383 debug("correcting event to event[{0}, {1}]".format(k, v)) 384 385 diffs = [] 386 if logcat_event_time.get(KERNEL_TIME_KEY) is None: 387 print("kernel time not captured in logcat") 388 else: 389 diffs.append((logcat_event_time[KERNEL_TIME_KEY], logcat_event_time[KERNEL_TIME_KEY])) 390 391 if logcat_event_time.get(BOOT_ANIM_END_TIME_KEY) and dmesg_event_time.get(BOOT_ANIM_END_TIME_KEY): 392 diffs.append((logcat_event_time[BOOT_ANIM_END_TIME_KEY],\ 393 logcat_event_time[BOOT_ANIM_END_TIME_KEY] -\ 394 dmesg_event_time[BOOT_ANIM_END_TIME_KEY])) 395 if not dmesg_event_time.get(KERNEL_BOOT_COMPLETE): 396 print("BootAnimEnd time or BootComplete-kernel not captured in both log" +\ 397 ", cannot get time diff") 398 print("dmesg {} logcat {}".format(dmesg_event_time, logcat_event_time)) 399 return None, None, None, None, None, None 400 diffs.append((logcat_event_time[LOGCAT_BOOT_COMPLETE],\ 401 logcat_event_time[LOGCAT_BOOT_COMPLETE] - dmesg_event_time[KERNEL_BOOT_COMPLETE])) 402 403 for k, v in logcat_event_time.items(): 404 debug("event[{0}, {1}]".format(k, v)) 405 events[k] = v 406 if k in dmesg_event_time: 407 debug("{0} is in dmesg".format(k)) 408 events[k] = dmesg_event_time[k] 409 replaced_from_dmesg.add(k) 410 else: 411 events_to_correct.append(k) 412 413 diff_prev = diffs[0] 414 for k in events_to_correct: 415 diff = diffs[0] 416 while diff[0] < events[k] and len(diffs) > 1: 417 diffs.pop(0) 418 diff_prev = diff 419 diff = diffs[0] 420 events[k] = events[k] - diff[1] 421 if events[k] < 0.0: 422 if events[k] < -0.1: # maybe previous one is better fit 423 events[k] = events[k] + diff[1] - diff_prev[1] 424 else: 425 events[k] = 0.0 426 427 data_points = collections.OrderedDict() 428 429 print("-----------------") 430 print("ro.boottime.*: time") 431 for item in list(boottime_events.items()): 432 print('{0:30}: {1:<7.5} {2}'.format(item[0], item[1],\ 433 "*time taken" if item[0].startswith("init.") else "")) 434 print("-----------------") 435 436 if args.timings: 437 kernel_timing_points, _ = generate_timing_points(kernel_timing_events, timings_pattern) 438 logcat_timing_points, logcat_monitor_contentions =\ 439 generate_timing_points(logcat_timing_events, timings_pattern) 440 dump_timing_points("Kernel", kernel_timing_points) 441 dump_timing_points("Logcat", logcat_timing_points) 442 dump_monitor_contentions(logcat_monitor_contentions) 443 444 for item in sorted(list(events.items()), key=operator.itemgetter(1)): 445 data_points[item[0]] = { 446 'value': item[1], 447 'from_dmesg': item[0] in replaced_from_dmesg, 448 'logcat_value': logcat_original_time[item[0]] 449 } 450 # add times with bootloader 451 if events.get("BootComplete") and boottime_events.get("bootloader"): 452 total = events["BootComplete"] + boottime_events["bootloader"] 453 data_points["*BootComplete+Bootloader"] = { 454 'value': total, 455 'from_dmesg': False, 456 'logcat_value': 0.0 457 } 458 if events.get("LauncherStart") and boottime_events.get("bootloader"): 459 total = events["LauncherStart"] + boottime_events["bootloader"] 460 data_points["*LauncherStart+Bootloader"] = { 461 'value': total, 462 'from_dmesg': False, 463 'logcat_value': 0.0 464 } 465 for k, v in data_points.items(): 466 print('{0:30}: {1:<7.5} {2:1} ({3})'.format( 467 k, v['value'], '*' if v['from_dmesg'] else '', v['logcat_value'])) 468 469 print('\n* - event time was obtained from dmesg log\n') 470 471 if events[LOGCAT_BOOT_COMPLETE] > error_time and not args.ignore: 472 capture_bugreport("bootuptoolong", events[LOGCAT_BOOT_COMPLETE]) 473 474 for k, v in components_to_monitor.items(): 475 logcat_value_measured = logcat_timing_points.get(k) 476 kernel_value_measured = kernel_timing_points.get(k) 477 data_from_data_points = data_points.get(k) 478 if logcat_value_measured and logcat_value_measured > v: 479 capture_bugreport(k + "-" + str(logcat_value_measured), events[LOGCAT_BOOT_COMPLETE]) 480 break 481 elif kernel_value_measured and kernel_value_measured > v: 482 capture_bugreport(k + "-" + str(kernel_value_measured), events[LOGCAT_BOOT_COMPLETE]) 483 break 484 elif data_from_data_points and data_from_data_points['value'] * 1000.0 > v: 485 capture_bugreport(k + "-" + str(data_from_data_points['value']), events[LOGCAT_BOOT_COMPLETE]) 486 break 487 488 if args.fs_check: 489 fs_stat = None 490 if logcat_events.get("FsStat"): 491 fs_stat_pattern = cfg["events"]["FsStat"] 492 m = re.search(fs_stat_pattern, logcat_events.get("FsStat")) 493 if m: 494 fs_stat = m.group(1) 495 print('fs_stat:', fs_stat) 496 497 if fs_stat: 498 fs_stat_val = int(fs_stat, 0) 499 if (fs_stat_val & ~0x17) != 0: 500 capture_bugreport("fs_stat_" + fs_stat, events[LOGCAT_BOOT_COMPLETE]) 501 502 return data_points, kernel_timing_points, logcat_timing_points, boottime_events, shutdown_events,\ 503 shutdown_timing_events 504 505def debug(string): 506 if DEBUG: 507 print(string) 508 509def extract_timing(s, patterns): 510 for _, p in patterns.items(): 511 m = p.search(s) 512 if m: 513 timing_dict = m.groupdict() 514 return timing_dict['name'], float(timing_dict['time']) 515 return None, None 516 517def init_arguments(): 518 parser = argparse.ArgumentParser(description='Measures boot time.') 519 parser.add_argument('-r', '--reboot', dest='reboot', 520 action='store_true', 521 help='reboot device for measurement', ) 522 parser.add_argument('-o', '--output', dest='output', type=str, 523 help='Output directory where results are stored') 524 parser.add_argument('-c', '--config', dest='config', 525 default='config.yaml', type=argparse.FileType('r'), 526 help='config file for the tool', ) 527 parser.add_argument('-s', '--stressfs', dest='stressfs', 528 default='', type=str, 529 help='APK file for the stressfs tool used to write to the data partition ' +\ 530 'during shutdown') 531 parser.add_argument('-n', '--iterate', dest='iterate', type=int, default=1, 532 help='number of time to repeat the measurement', ) 533 parser.add_argument('-g', '--ignore', dest='ignore', action='store_true', 534 help='ignore too big values error', ) 535 parser.add_argument('-t', '--timings', dest='timings', action='store_true', 536 help='print individual component times', default=True, ) 537 parser.add_argument('-p', '--serial', dest='serial', action='store', 538 help='android device serial number') 539 parser.add_argument('-e', '--errortime', dest='errortime', action='store', 540 help='handle bootup time bigger than this as error') 541 parser.add_argument('-w', '--maxwaittime', dest='maxwaittime', action='store', 542 help='wait for up to this time to collect logs. Retry after this time.' +\ 543 ' Default is 200 sec.') 544 parser.add_argument('-f', '--fs_check', dest='fs_check', 545 action='store_true', 546 help='check fs_stat after reboot', ) 547 parser.add_argument('-a', '--adb_reboot', dest='adb_reboot', 548 action='store_true', 549 help='reboot with adb reboot', ) 550 parser.add_argument('-v', '--permissive', dest='permissive', 551 action='store_true', 552 help='set selinux into permissive before reboot', ) 553 parser.add_argument('-m', '--componentmonitor', dest='componentmonitor', action='store', 554 help='capture bugreport if specified timing component is taking more than ' +\ 555 'certain time. Unlike errortime, the result will not be rejected in' +\ 556 'averaging. Format is key1=time1,key2=time2...') 557 parser.add_argument('-b', '--bootchart', dest='bootchart', 558 action='store_true', 559 help='collect bootchart from the device.', ) 560 parser.add_argument('-y', '--systrace', dest='systrace', 561 action='store_true', 562 help='collect systrace from the device. kernel trace should be already enabled', ) 563 parser.add_argument('-W', '--carwatchdog', dest='carwatchdog', action='store_true', 564 help='collect carwatchdog boot stats') 565 parser.add_argument('-G', '--buffersize', dest='buffersize', action='store', type=str, 566 default=None, 567 help='set logcat buffersize') 568 return parser.parse_args() 569 570def handle_zygote_event(zygote_pids, events, event, line): 571 words = line.split() 572 if len(words) > 1: 573 pid = int(words[1]) 574 if len(zygote_pids) == 2: 575 if pid == zygote_pids[1]: # secondary 576 event = event + "-secondary" 577 elif len(zygote_pids) == 1: 578 if zygote_pids[0] != pid: # new pid, need to decide if old ones were secondary 579 primary_pid = min(pid, zygote_pids[0]) 580 secondary_pid = max(pid, zygote_pids[0]) 581 zygote_pids.pop() 582 zygote_pids.append(primary_pid) 583 zygote_pids.append(secondary_pid) 584 if pid == primary_pid: # old one was secondary: 585 move_to_secondary = [] 586 for k, l in events.items(): 587 if k.startswith("zygote"): 588 move_to_secondary.append((k, l)) 589 for item in move_to_secondary: 590 del events[item[0]] 591 if item[0].endswith("-secondary"): 592 print("Secondary already exists for event %s while found new pid %d, primary %d "\ 593 % (item[0], secondary_pid, primary_pid)) 594 else: 595 events[item[0] + "-secondary"] = item[1] 596 else: 597 event = event + "-secondary" 598 else: 599 zygote_pids.append(pid) 600 events[event] = line 601 602def update_name_if_already_exist(events, name): 603 existing_event = events.get(name) 604 i = 0 605 new_name = name 606 while existing_event: 607 i += 1 608 new_name = name + "_" + str(i) 609 existing_event = events.get(new_name) 610 return new_name 611 612def collect_logcat_for_shutdown(capture_log_on_error, shutdown_events_pattern,\ 613 log_capture_conditions): 614 events = collections.OrderedDict() 615 # shutdown does not have timing_events but calculated from checking Xyz - XyzDone / XyzTimeout 616 timing_events = collections.OrderedDict() 617 process = subprocess.Popen(ADB_CMD + ' logcat -b all -v epoch', shell=True, 618 stdout=subprocess.PIPE) 619 lines = [] 620 capture_log = False 621 shutdown_start_time = 0 622 while True: 623 line = process.stdout.readline() 624 if not line: 625 break 626 line = line.decode('utf-8', 'ignore').lstrip().rstrip() 627 lines.append(line) 628 event = get_boot_event(line, shutdown_events_pattern) 629 if not event: 630 continue 631 time = extract_a_time(line, TIME_LOGCAT, float) 632 if time is None: 633 print("cannot get time from: " + line) 634 continue 635 if shutdown_start_time == 0: 636 shutdown_start_time = time 637 time = time - shutdown_start_time 638 events[event] = time 639 time_limit1 = log_capture_conditions.get(event) 640 if time_limit1 and time_limit1 <= time: 641 capture_log = True 642 pair_event = None 643 if event.endswith('Done'): 644 pair_event = event[:-4] 645 elif event.endswith('Timeout'): 646 pair_event = event[:-7] 647 if capture_log_on_error: 648 capture_log = True 649 if not pair_event: 650 continue 651 start_time = events.get(pair_event) 652 if not start_time: 653 print("No start event for " + event) 654 continue 655 time_spent = time - start_time 656 timing_event_name = pair_event + "Duration" 657 timing_events[timing_event_name] = time_spent 658 time_limit2 = log_capture_conditions.get(timing_event_name) 659 if time_limit2 and time_limit2 <= time_spent: 660 capture_log = True 661 662 if capture_log: 663 now = datetime.now() 664 log_file = ("shutdownlog-error-%s.txt") % (now.strftime("%Y-%m-%d-%H-%M-%S")) 665 print("Shutdown error, capture log to %s" % (log_file)) 666 with open(log_file, 'w') as f: 667 f.write('\n'.join(lines)) 668 return events, timing_events 669 670def log_timeout(time_left, stop_events, events, timing_events): 671 print("timeout waiting for event, continue", time_left) 672 print(" remaininig events {}, event {} timing events {}".\ 673 format(stop_events, events, timing_events)) 674 675def collect_events(search_events, command, timings, stop_events, disable_timing_after_zygote): 676 events = collections.OrderedDict() 677 timing_events = {} 678 679 data_available = stop_events is None 680 zygote_pids = [] 681 start_time = time.time() 682 zygote_found = False 683 line = None 684 print("remaining stop_events:", stop_events) 685 init = True 686 while True: 687 if init: 688 process = subprocess.Popen(command, shell=True, stdout=subprocess.PIPE) 689 read_poll = select.poll() 690 read_poll.register(process.stdout, select.POLLIN) 691 init = False 692 if len(stop_events) == 0: 693 break 694 time_left = start_time + max_wait_time - time.time() 695 if time_left <= 0: 696 log_timeout(time_left, stop_events, events, timing_events) 697 break 698 polled_events = read_poll.poll(time_left * 1000.0) 699 # adb logcat subprocess is auto-terminated when the adb connection is lost. 700 # Thus, check for the subprocess return code and reconnect to the device if 701 # needed. Otherwise, the logcat events cannot be polled completely. 702 if process.poll() is not None: 703 print("adb might be disconnected?\nRetrying to connect.") 704 run_adb_cmd('wait-for-device') 705 print(" reconnected") 706 init = True 707 continue 708 if len(polled_events) == 0: 709 log_timeout(time_left, stop_events, events, timing_events) 710 break 711 for polled_event in polled_events: 712 if polled_event[1] == select.POLLIN: 713 line = process.stdout.readline().decode('utf-8', 'ignore') 714 else: 715 if polled_event[1] == select.POLLHUP: 716 if len(stop_events) == 0: 717 break; 718 # adb connection lost 719 print("poll error waiting for event, adb lost?") 720 if time_left > 0: 721 print("retry adb") 722 run_adb_cmd('wait-for-device') 723 print(" reconnected") 724 init = True 725 continue 726 else: 727 break 728 if not data_available: 729 print("Collecting data samples from '%s'. Please wait...\n" % command) 730 data_available = True 731 event = get_boot_event(line, search_events) 732 if event: 733 debug("event[{0}] captured: {1}".format(event, line)) 734 if event == "starting_zygote": 735 events[event] = line 736 zygote_found = True 737 elif event.startswith("zygote"): 738 handle_zygote_event(zygote_pids, events, event, line) 739 else: 740 new_event = update_name_if_already_exist(events, event) 741 events[new_event] = line 742 if event in stop_events: 743 stop_events.remove(event) 744 print("remaining stop_events:", stop_events) 745 746 timing_event = get_boot_event(line, timings) 747 if timing_event and (not disable_timing_after_zygote or not zygote_found): 748 if timing_event not in timing_events: 749 timing_events[timing_event] = [] 750 timing_events[timing_event].append(line) 751 debug("timing_event[{0}] captured: {1}".format(timing_event, line)) 752 753 process.terminate() 754 return events, timing_events 755 756def fetch_boottime_property(): 757 cmd = ADB_CMD + ' shell su root getprop' 758 events = {} 759 process = subprocess.Popen(cmd, shell=True, stdout=subprocess.PIPE) 760 out = process.stdout 761 pattern = re.compile(BOOT_PROP) 762 pattern_bootloader = re.compile(BOOTLOADER_TIME_PROP) 763 bootloader_time = 0.0 764 for line in out: 765 line = line.decode('utf-8', 'ignore') 766 match = pattern.match(line) 767 if match: 768 if match.group(1).startswith("init."): 769 events[match.group(1)] = float(match.group(2)) / 1000.0 #ms to s 770 else: 771 events[match.group(1)] = float(match.group(2)) / 1000000000.0 #ns to s 772 match = pattern_bootloader.match(line) 773 if match: 774 items = match.group(1).split(",") 775 for item in items: 776 entry_pair = item.split(":") 777 entry_name = entry_pair[0] 778 time_spent = float(entry_pair[1]) / 1000 #ms to s 779 if entry_name != "SW": 780 bootloader_time = bootloader_time + time_spent 781 ordered_event = collections.OrderedDict() 782 if bootloader_time != 0.0: 783 ordered_event["bootloader"] = bootloader_time 784 for item in sorted(list(events.items()), key=operator.itemgetter(1)): 785 ordered_event[item[0]] = item[1] 786 return ordered_event 787 788 789def get_boot_event(line, events): 790 for event_key, event_pattern in events.items(): 791 if event_pattern.search(line): 792 return event_key 793 return None 794 795def extract_a_time(line, pattern, date_transform_function): 796 found = re.findall(pattern, line) 797 if len(found) > 0: 798 return date_transform_function(found[0]) 799 else: 800 return None 801 802def extract_time(events, pattern, date_transform_function): 803 result = collections.OrderedDict() 804 for event, data in events.items(): 805 time = extract_a_time(data, pattern, date_transform_function) 806 if time is not None: 807 result[event] = time 808 else: 809 print("Failed to find time for event: ", event, data) 810 return result 811 812 813def do_reboot(serial, use_adb_reboot): 814 # do not update time 815 run_adb_cmd('shell settings put global auto_time 0') 816 run_adb_cmd('shell settings put global auto_time_zone 0') 817 original_devices = subprocess.check_output("adb devices", shell=True).decode('utf-8', 'ignore') 818 if use_adb_reboot: 819 print('Rebooting the device using adb reboot') 820 run_adb_cmd('reboot') 821 else: 822 print('Rebooting the device using svc power reboot') 823 run_adb_shell_cmd_as_root('svc power reboot') 824 # Wait for the device to go away 825 retry = 0 826 while retry < 20: 827 current_devices = subprocess.check_output("adb devices", shell=True).decode('utf-8', 'ignore') 828 if original_devices != current_devices: 829 if not serial or (serial and current_devices.find(serial) < 0): 830 return True 831 time.sleep(1) 832 retry += 1 833 return False 834 835def reboot(serial, use_stressfs, permissive, use_adb_reboot, adb_buffersize=None): 836 if use_stressfs: 837 print('Starting write to data partition') 838 run_adb_shell_cmd('am start' +\ 839 ' -n com.android.car.test.stressfs/.WritingActivity' +\ 840 ' -a com.android.car.test.stressfs.START') 841 # Give this app some time to start. 842 time.sleep(1) 843 if permissive: 844 run_adb_shell_cmd_as_root('setenforce 0') 845 846 retry = 0 847 while retry < 5: 848 if do_reboot(serial, use_adb_reboot): 849 break 850 retry += 1 851 852 print('Waiting the device') 853 run_adb_cmd('wait-for-device') 854 print(' found a device') 855 856 if adb_buffersize is not None: 857 # increase the buffer size 858 if run_adb_cmd('logcat -G {}'.format(adb_buffersize)) != 0: 859 debug('Fail to set logcat buffer size as {}'.format(adb_buffersize)) 860 861''' 862Runs adb command. If do_return_result is true then output of command is 863returned otherwise an empty string is returned. 864''' 865def run_adb_cmd(cmd, do_return_result=False): 866 if do_return_result: 867 return subprocess.check_output(ADB_CMD + ' ' + cmd, shell=True).decode('utf-8', 'ignore').strip() 868 subprocess.call(ADB_CMD + ' ' + cmd, shell=True) 869 return "" 870 871def run_adb_shell_cmd(cmd, do_return_result=False): 872 return run_adb_cmd('shell ' + cmd, do_return_result) 873 874def run_adb_shell_cmd_as_root(cmd, do_return_result=False): 875 return run_adb_shell_cmd('su root ' + cmd, do_return_result) 876 877def logcat_time_func(offset_year): 878 def f(date_str): 879 ndate = datetime.datetime.strptime(str(offset_year) + '-' + 880 date_str, '%Y-%m-%d %H:%M:%S.%f') 881 return datetime_to_unix_time(ndate) 882 return f 883 884def datetime_to_unix_time(ndate): 885 return time.mktime(ndate.timetuple()) + ndate.microsecond/1000000.0 886 887def stddev(data): 888 items_count = len(data) 889 avg = sum(data) / items_count 890 sq_diffs_sum = sum([(v - avg) ** 2 for v in data]) 891 variance = sq_diffs_sum / items_count 892 return math.sqrt(variance) 893 894def grab_bootchart(boot_chart_file_path): 895 subprocess.run("$ANDROID_BUILD_TOP/system/core/init/grab-bootchart.sh", shell=True, 896 stdout=subprocess.DEVNULL) 897 print("Saving boot chart as " + boot_chart_file_path + ".tgz") 898 subprocess.call('cp /tmp/android-bootchart/bootchart.tgz ' + boot_chart_file_path + '.tgz', \ 899 shell=True) 900 subprocess.call('cp ./bootchart.png ' + boot_chart_file_path + '.png', shell=True) 901 902def grab_systrace(systrace_file_path_prefix): 903 trace_file = systrace_file_path_prefix + "_trace.txt" 904 with open(trace_file, 'w') as f: 905 f.write("TRACE:\n") 906 run_adb_shell_cmd_as_root("cat /d/tracing/trace >> " + trace_file) 907 html_file = systrace_file_path_prefix + ".html" 908 subprocess.call("$ANDROID_BUILD_TOP/external/chromium-trace/systrace.py --from-file=" + trace_file + " -o " +\ 909 html_file, shell=True) 910 911def capture_build_info(out_dir, build_info_file_name): 912 fingerprint = run_adb_shell_cmd('getprop ro.build.fingerprint', True) 913 brand = run_adb_shell_cmd('getprop ro.product.brand', True) 914 product = run_adb_shell_cmd('getprop ro.product.name', True) 915 device = run_adb_shell_cmd('getprop ro.product.device', True) 916 version_release = run_adb_shell_cmd('getprop ro.build.version.release', True) 917 id = run_adb_shell_cmd('getprop ro.build.id', True) 918 version_incremental = run_adb_shell_cmd('getprop ro.build.version.incremental', True) 919 type = run_adb_shell_cmd('getprop ro.build.type', True) 920 tags = run_adb_shell_cmd('getprop ro.build.tags', True) 921 sdk = run_adb_shell_cmd('getprop ro.build.version.sdk', True) 922 platform_minor = run_adb_shell_cmd('getprop ro.android.car.version.platform_minor', True) 923 codename = run_adb_shell_cmd('getprop ro.build.version.codename', True) 924 carwatchdog_collection_interval = run_adb_shell_cmd('getprop ro.carwatchdog.system_event_collection_interval', True) 925 carwatchdog_post_event_duration = run_adb_shell_cmd('getprop ro.carwatchdog.post_system_event_duration', True) 926 carwatchdog_top_n_category = run_adb_shell_cmd('getprop ro.carwatchdog.top_n_stats_per_category', True) 927 carwatchdog_top_n_subcategory = run_adb_shell_cmd('getprop ro.carwatchdog.top_n_stats_per_subcategory', True) 928 929 # TODO: Change file format to JSON to avoid custom parser 930 build_info = [] 931 build_info.append('Build information: ') 932 build_info.append('-' * 20) 933 build_info.append('fingerprint: ' + fingerprint) 934 build_info.append('brand: ' + brand) 935 build_info.append('product: ' + product) 936 build_info.append('device: ' + device) 937 build_info.append('version.release: ' + version_release) 938 build_info.append('id: ' + id) 939 build_info.append('version.incremental: ' + version_incremental) 940 build_info.append('type: ' + type) 941 build_info.append('tags: ' + tags) 942 build_info.append('sdk: ' + sdk) 943 build_info.append('platform minor version: ' + platform_minor) 944 build_info.append('codename: ' + codename) 945 build_info.append('carwatchdog collection interval (s): ' + carwatchdog_collection_interval) 946 build_info.append('carwatchdog post event duration (s): ' + carwatchdog_post_event_duration) 947 build_info.append('carwatchdog top N packages: ' + carwatchdog_top_n_category) 948 build_info.append('carwatchdog top N processes: ' + carwatchdog_top_n_subcategory) 949 950 build_info_str = '\n'.join(build_info) 951 952 with open(out_dir + '/' + build_info_file_name, 'w') as f: 953 f.write(build_info_str) 954 955def generate_proto(dump_file, build_info_file, out_proto_file): 956 subprocess.run("{} -f {} -b {} -d {}".format(CARWATCHDOG_PARSER_CMD, 957 dump_file, 958 build_info_file, 959 out_proto_file), 960 shell=True, stdout=subprocess.DEVNULL) 961 962def grab_carwatchdog_bootstats(result_dir): 963 carwatchdog_state = run_adb_shell_cmd_as_root('getprop init.svc.carwatchdogd', True) 964 if carwatchdog_state != "running": 965 print('carwatchdog (-d) flag set but CarWatchdog is not running on device') 966 return 967 elif not result_dir: 968 print('carwatchdog needs the output directory to be specified.') 969 return 970 print("Capturing carwatchdog stats") 971 build_info_file_name = "device_build_info.txt" 972 capture_build_info(result_dir, build_info_file_name) 973 974 # Capture CW dump and save dump to txt 975 dump_file_name = result_dir + '/carwatchdog_dump.txt' 976 subprocess.call(CARWATCHDOG_DUMP_COMMAND + " > " + dump_file_name, shell=True) 977 978 # Generate proto from dump 979 build_info_file_path = result_dir + '/' + build_info_file_name 980 out_proto_file_path = result_dir + '/carwatchdog_perf_stats_out.pb' 981 generate_proto(dump_file_name, build_info_file_path, out_proto_file_path) 982 983 984if __name__ == '__main__': 985 main() 986