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