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