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