1#!/usr/bin/python 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 = "\[\s*(\d+\.\d+)\]" 40TIME_LOGCAT = "[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 = "\[ro\.boottime\.([^\]]+)\]:\s+\[(\d+)\]" 52BOOTLOADER_TIME_PROP = "\[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) 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'].iteritems()} 98 timing_events_pattern = {key: re.compile(pattern) 99 for key, pattern in cfg['timings'].iteritems()} 100 shutdown_events_pattern = {key: re.compile(pattern) 101 for key, pattern in cfg['shutdown_events'].iteritems()} 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.iteritems(): 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.iteritems(): 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.iteritems(): 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.iteritems(): 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.iteritems(): 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.iteritems(): 164 if not k 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 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 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 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 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 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.iteritems(): 255 for v in l: 256 name, time_v, dict = 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 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(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 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 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 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( 329 logcat_events, TIME_LOGCAT, float); 330 logcat_original_time = extract_time( 331 logcat_events, TIME_LOGCAT, str); 332 dmesg_event_time = extract_time( 333 dmesg_events, TIME_DMESG, float); 334 boottime_events = fetch_boottime_property() 335 events = {} 336 diff_time = 0 337 max_time = 0 338 events_to_correct = [] 339 replaced_from_dmesg = set() 340 341 time_correction_delta = 0 342 time_correction_time = 0 343 if ('time_correction_key' in cfg 344 and cfg['time_correction_key'] in logcat_events): 345 match = search_events[cfg['time_correction_key']].search( 346 logcat_events[cfg['time_correction_key']]) 347 if match and logcat_event_time[cfg['time_correction_key']]: 348 time_correction_delta = float(match.group(1)) 349 time_correction_time = logcat_event_time[cfg['time_correction_key']] 350 351 debug("time_correction_delta = {0}, time_correction_time = {1}".format( 352 time_correction_delta, time_correction_time)) 353 354 for k, v in logcat_event_time.iteritems(): 355 if v <= time_correction_time: 356 logcat_event_time[k] += time_correction_delta 357 v = v + time_correction_delta 358 debug("correcting event to event[{0}, {1}]".format(k, v)) 359 360 if not logcat_event_time.get(KERNEL_TIME_KEY): 361 print "kernel time not captured in logcat, cannot get time diff" 362 return None, None, None, None, None, None 363 diffs = [] 364 diffs.append((logcat_event_time[KERNEL_TIME_KEY], logcat_event_time[KERNEL_TIME_KEY])) 365 if logcat_event_time.get(BOOT_ANIM_END_TIME_KEY) and dmesg_event_time.get(BOOT_ANIM_END_TIME_KEY): 366 diffs.append((logcat_event_time[BOOT_ANIM_END_TIME_KEY],\ 367 logcat_event_time[BOOT_ANIM_END_TIME_KEY] -\ 368 dmesg_event_time[BOOT_ANIM_END_TIME_KEY])) 369 if not dmesg_event_time.get(KERNEL_BOOT_COMPLETE): 370 print "BootAnimEnd time or BootComplete-kernel not captured in both log" +\ 371 ", cannot get time diff" 372 return None, None, None, None, None, None 373 diffs.append((logcat_event_time[LOGCAT_BOOT_COMPLETE],\ 374 logcat_event_time[LOGCAT_BOOT_COMPLETE] - dmesg_event_time[KERNEL_BOOT_COMPLETE])) 375 376 for k, v in logcat_event_time.iteritems(): 377 debug("event[{0}, {1}]".format(k, v)) 378 events[k] = v 379 if k in dmesg_event_time: 380 debug("{0} is in dmesg".format(k)) 381 events[k] = dmesg_event_time[k] 382 replaced_from_dmesg.add(k) 383 else: 384 events_to_correct.append(k) 385 386 diff_prev = diffs[0] 387 for k in events_to_correct: 388 diff = diffs[0] 389 while diff[0] < events[k] and len(diffs) > 1: 390 diffs.pop(0) 391 diff_prev = diff 392 diff = diffs[0] 393 events[k] = events[k] - diff[1] 394 if events[k] < 0.0: 395 if events[k] < -0.1: # maybe previous one is better fit 396 events[k] = events[k] + diff[1] - diff_prev[1] 397 else: 398 events[k] = 0.0 399 400 data_points = collections.OrderedDict() 401 402 print "-----------------" 403 print "ro.boottime.*: time" 404 for item in boottime_events.items(): 405 print '{0:30}: {1:<7.5} {2}'.format(item[0], item[1],\ 406 "*time taken" if item[0].startswith("init.") else "") 407 print "-----------------" 408 409 if args.timings: 410 kernel_timing_points, _ = generate_timing_points(kernel_timing_events, timings_pattern) 411 logcat_timing_points, logcat_monitor_contentions =\ 412 generate_timing_points(logcat_timing_events, timings_pattern) 413 dump_timing_points("Kernel", kernel_timing_points) 414 dump_timing_points("Logcat", logcat_timing_points) 415 dump_monitor_contentions(logcat_monitor_contentions) 416 417 for item in sorted(events.items(), key=operator.itemgetter(1)): 418 data_points[item[0]] = { 419 'value': item[1], 420 'from_dmesg': item[0] in replaced_from_dmesg, 421 'logcat_value': logcat_original_time[item[0]] 422 } 423 # add times with bootloader 424 if events.get("BootComplete") and boottime_events.get("bootloader"): 425 total = events["BootComplete"] + boottime_events["bootloader"] 426 data_points["*BootComplete+Bootloader"] = { 427 'value': total, 428 'from_dmesg': False, 429 'logcat_value': 0.0 430 } 431 if events.get("LauncherStart") and boottime_events.get("bootloader"): 432 total = events["LauncherStart"] + boottime_events["bootloader"] 433 data_points["*LauncherStart+Bootloader"] = { 434 'value': total, 435 'from_dmesg': False, 436 'logcat_value': 0.0 437 } 438 for k, v in data_points.iteritems(): 439 print '{0:30}: {1:<7.5} {2:1} ({3})'.format( 440 k, v['value'], '*' if v['from_dmesg'] else '', v['logcat_value']) 441 442 print '\n* - event time was obtained from dmesg log\n' 443 444 if events[LOGCAT_BOOT_COMPLETE] > error_time and not args.ignore: 445 capture_bugreport("bootuptoolong", events[LOGCAT_BOOT_COMPLETE]) 446 447 for k, v in components_to_monitor.iteritems(): 448 logcat_value_measured = logcat_timing_points.get(k) 449 kernel_value_measured = kernel_timing_points.get(k) 450 data_from_data_points = data_points.get(k) 451 if logcat_value_measured and logcat_value_measured > v: 452 capture_bugreport(k + "-" + str(logcat_value_measured), events[LOGCAT_BOOT_COMPLETE]) 453 break 454 elif kernel_value_measured and kernel_value_measured > v: 455 capture_bugreport(k + "-" + str(kernel_value_measured), events[LOGCAT_BOOT_COMPLETE]) 456 break 457 elif data_from_data_points and data_from_data_points['value'] * 1000.0 > v: 458 capture_bugreport(k + "-" + str(data_from_data_points['value']), events[LOGCAT_BOOT_COMPLETE]) 459 break 460 461 if args.fs_check: 462 fs_stat = None 463 if logcat_events.get("FsStat"): 464 fs_stat_pattern = cfg["events"]["FsStat"] 465 m = re.search(fs_stat_pattern, logcat_events.get("FsStat")) 466 if m: 467 fs_stat = m.group(1) 468 print 'fs_stat:', fs_stat 469 470 if fs_stat: 471 fs_stat_val = int(fs_stat, 0) 472 if (fs_stat_val & ~0x17) != 0: 473 capture_bugreport("fs_stat_" + fs_stat, events[LOGCAT_BOOT_COMPLETE]) 474 475 return data_points, kernel_timing_points, logcat_timing_points, boottime_events, shutdown_events,\ 476 shutdown_timing_events 477 478def debug(string): 479 if DEBUG: 480 print string 481 482def extract_timing(s, patterns): 483 for k, p in patterns.iteritems(): 484 m = p.search(s) 485 if m: 486 dict = m.groupdict() 487 return dict['name'], float(dict['time']), dict 488 return None, None 489 490def init_arguments(): 491 parser = argparse.ArgumentParser(description='Measures boot time.') 492 parser.add_argument('-r', '--reboot', dest='reboot', 493 action='store_true', 494 help='reboot device for measurement', ) 495 parser.add_argument('-c', '--config', dest='config', 496 default='config.yaml', type=argparse.FileType('r'), 497 help='config file for the tool', ) 498 parser.add_argument('-s', '--stressfs', dest='stressfs', 499 default='', type=str, 500 help='APK file for the stressfs tool used to write to the data partition ' +\ 501 'during shutdown') 502 parser.add_argument('-n', '--iterate', dest='iterate', type=int, default=1, 503 help='number of time to repeat the measurement', ) 504 parser.add_argument('-g', '--ignore', dest='ignore', action='store_true', 505 help='ignore too big values error', ) 506 parser.add_argument('-t', '--timings', dest='timings', action='store_true', 507 help='print individual component times', default=True, ) 508 parser.add_argument('-p', '--serial', dest='serial', action='store', 509 help='android device serial number') 510 parser.add_argument('-e', '--errortime', dest='errortime', action='store', 511 help='handle bootup time bigger than this as error') 512 parser.add_argument('-w', '--maxwaittime', dest='maxwaittime', action='store', 513 help='wait for up to this time to collect logs. Retry after this time.' +\ 514 ' Default is 200 sec.') 515 parser.add_argument('-f', '--fs_check', dest='fs_check', 516 action='store_true', 517 help='check fs_stat after reboot', ) 518 parser.add_argument('-a', '--adb_reboot', dest='adb_reboot', 519 action='store_true', 520 help='reboot with adb reboot', ) 521 parser.add_argument('-v', '--permissive', dest='permissive', 522 action='store_true', 523 help='set selinux into permissive before reboot', ) 524 parser.add_argument('-m', '--componentmonitor', dest='componentmonitor', action='store', 525 help='capture bugreport if specified timing component is taking more than ' +\ 526 'certain time. Unlike errortime, the result will not be rejected in' +\ 527 'averaging. Format is key1=time1,key2=time2...') 528 parser.add_argument('-b', '--bootchart', dest='bootchart', 529 action='store_true', 530 help='collect bootchart from the device.', ) 531 parser.add_argument('-y', '--systrace', dest='systrace', 532 action='store_true', 533 help='collect systrace from the device. kernel trace should be already enabled', ) 534 parser.add_argument('-G', '--buffersize', dest='buffersize', action='store', type=str, 535 default=None, 536 help='set logcat buffersize') 537 return parser.parse_args() 538 539def handle_zygote_event(zygote_pids, events, event, line): 540 words = line.split() 541 if len(words) > 1: 542 pid = int(words[1]) 543 if len(zygote_pids) == 2: 544 if pid == zygote_pids[1]: # secondary 545 event = event + "-secondary" 546 elif len(zygote_pids) == 1: 547 if zygote_pids[0] != pid: # new pid, need to decide if old ones were secondary 548 primary_pid = min(pid, zygote_pids[0]) 549 secondary_pid = max(pid, zygote_pids[0]) 550 zygote_pids.pop() 551 zygote_pids.append(primary_pid) 552 zygote_pids.append(secondary_pid) 553 if pid == primary_pid: # old one was secondary: 554 move_to_secondary = [] 555 for k, l in events.iteritems(): 556 if k.startswith("zygote"): 557 move_to_secondary.append((k, l)) 558 for item in move_to_secondary: 559 del events[item[0]] 560 if item[0].endswith("-secondary"): 561 print "Secondary already exists for event %s while found new pid %d, primary %d "\ 562 % (item[0], secondary_pid, primary_pid) 563 else: 564 events[item[0] + "-secondary"] = item[1] 565 else: 566 event = event + "-secondary" 567 else: 568 zygote_pids.append(pid) 569 events[event] = line 570 571def update_name_if_already_exist(events, name): 572 existing_event = events.get(name) 573 i = 0 574 new_name = name 575 while existing_event: 576 i += 1 577 new_name = name + "_" + str(i) 578 existing_event = events.get(new_name) 579 return new_name 580 581def collect_logcat_for_shutdown(capture_log_on_error, shutdown_events_pattern,\ 582 log_capture_conditions): 583 events = collections.OrderedDict() 584 # shutdown does not have timing_events but calculated from checking Xyz - XyzDone / XyzTimeout 585 timing_events = collections.OrderedDict() 586 process = subprocess.Popen(ADB_CMD + ' logcat -b all -v epoch', shell=True, 587 stdout=subprocess.PIPE); 588 lines = [] 589 capture_log = False 590 shutdown_start_time = 0 591 while (True): 592 line = process.stdout.readline().lstrip().rstrip() 593 if not line: 594 break 595 lines.append(line) 596 event = get_boot_event(line, shutdown_events_pattern); 597 if not event: 598 continue 599 time = extract_a_time(line, TIME_LOGCAT, float) 600 if not time: 601 print "cannot get time from: " + line 602 continue 603 if shutdown_start_time == 0: 604 shutdown_start_time = time 605 time = time - shutdown_start_time 606 events[event] = time 607 time_limit1 = log_capture_conditions.get(event) 608 if time_limit1 and time_limit1 <= time: 609 capture_log = True 610 pair_event = None 611 if event.endswith('Done'): 612 pair_event = event[:-4] 613 elif event.endswith('Timeout'): 614 pair_event = event[:-7] 615 if capture_log_on_error: 616 capture_log = True 617 if not pair_event: 618 continue 619 start_time = events.get(pair_event) 620 if not start_time: 621 print "No start event for " + event 622 continue 623 time_spent = time - start_time 624 timing_event_name = pair_event + "Duration" 625 timing_events[timing_event_name] = time_spent 626 time_limit2 = log_capture_conditions.get(timing_event_name) 627 if time_limit2 and time_limit2 <= time_spent: 628 capture_log = True 629 630 if capture_log: 631 now = datetime.now() 632 log_file = ("shutdownlog-error-%s.txt") % (now.strftime("%Y-%m-%d-%H-%M-%S")) 633 print "Shutdown error, capture log to %s" % (log_file) 634 with open(log_file, 'w') as f: 635 f.write('\n'.join(lines)) 636 return events, timing_events 637 638 639def collect_events(search_events, command, timings, stop_events, disable_timing_after_zygote): 640 events = collections.OrderedDict() 641 timing_events = {} 642 process = subprocess.Popen(command, shell=True, 643 stdout=subprocess.PIPE); 644 data_available = stop_events is None 645 zygote_pids = [] 646 start_time = time.time() 647 zygote_found = False 648 649 line = None 650 read_poll = select.poll() 651 read_poll.register(process.stdout, select.POLLIN) 652 while True: 653 time_left = start_time + max_wait_time - time.time() 654 if time_left <= 0: 655 print "timeout waiting for event, continue", time_left 656 break 657 read_r = read_poll.poll(time_left * 1000.0) 658 if len(read_r) > 0 and read_r[0][1] == select.POLLIN: 659 line = process.stdout.readline() 660 else: 661 print "poll timeout waiting for event, continue", time_left 662 break 663 if not data_available: 664 print "Collecting data samples from '%s'. Please wait...\n" % command 665 data_available = True 666 event = get_boot_event(line, search_events); 667 if event: 668 debug("event[{0}] captured: {1}".format(event, line)) 669 if event == "starting_zygote": 670 events[event] = line 671 zygote_found = True 672 elif event.startswith("zygote"): 673 handle_zygote_event(zygote_pids, events, event, line) 674 else: 675 new_event = update_name_if_already_exist(events, event) 676 events[new_event] = line 677 if event in stop_events: 678 stop_events.remove(event) 679 print "remaining stop_events:", stop_events 680 if len(stop_events) == 0: 681 break; 682 683 timing_event = get_boot_event(line, timings); 684 if timing_event and (not disable_timing_after_zygote or not zygote_found): 685 if timing_event not in timing_events: 686 timing_events[timing_event] = [] 687 timing_events[timing_event].append(line) 688 debug("timing_event[{0}] captured: {1}".format(timing_event, line)) 689 690 process.terminate() 691 return events, timing_events 692 693def fetch_boottime_property(): 694 cmd = ADB_CMD + ' shell su root getprop' 695 events = {} 696 process = subprocess.Popen(cmd, shell=True, 697 stdout=subprocess.PIPE); 698 out = process.stdout 699 pattern = re.compile(BOOT_PROP) 700 pattern_bootloader = re.compile(BOOTLOADER_TIME_PROP) 701 bootloader_time = 0.0 702 for line in out: 703 match = pattern.match(line) 704 if match: 705 if match.group(1).startswith("init."): 706 events[match.group(1)] = float(match.group(2)) / 1000.0 #ms to s 707 else: 708 events[match.group(1)] = float(match.group(2)) / 1000000000.0 #ns to s 709 match = pattern_bootloader.match(line) 710 if match: 711 items = match.group(1).split(",") 712 for item in items: 713 entry_pair = item.split(":") 714 entry_name = entry_pair[0] 715 time_spent = float(entry_pair[1]) / 1000 #ms to s 716 if entry_name != "SW": 717 bootloader_time = bootloader_time + time_spent 718 ordered_event = collections.OrderedDict() 719 if bootloader_time != 0.0: 720 ordered_event["bootloader"] = bootloader_time; 721 for item in sorted(events.items(), key=operator.itemgetter(1)): 722 ordered_event[item[0]] = item[1] 723 return ordered_event 724 725 726def get_boot_event(line, events): 727 for event_key, event_pattern in events.iteritems(): 728 if event_pattern.search(line): 729 return event_key 730 return None 731 732def extract_a_time(line, pattern, date_transform_function): 733 found = re.findall(pattern, line) 734 if len(found) > 0: 735 return date_transform_function(found[0]) 736 else: 737 return None 738 739def extract_time(events, pattern, date_transform_function): 740 result = collections.OrderedDict() 741 for event, data in events.iteritems(): 742 time = extract_a_time(data, pattern, date_transform_function) 743 if time: 744 result[event] = time 745 else: 746 print "Failed to find time for event: ", event, data 747 return result 748 749 750def do_reboot(serial, use_adb_reboot): 751 original_devices = subprocess.check_output("adb devices", shell=True) 752 if use_adb_reboot: 753 print 'Rebooting the device using adb reboot' 754 run_adb_cmd('reboot') 755 else: 756 print 'Rebooting the device using svc power reboot' 757 run_adb_shell_cmd_as_root('svc power reboot') 758 # Wait for the device to go away 759 retry = 0 760 while retry < 20: 761 current_devices = subprocess.check_output("adb devices", shell=True) 762 if original_devices != current_devices: 763 if not serial or (serial and current_devices.find(serial) < 0): 764 return True 765 time.sleep(1) 766 retry += 1 767 return False 768 769def reboot(serial, use_stressfs, permissive, use_adb_reboot, adb_buffersize=None): 770 if use_stressfs: 771 print 'Starting write to data partition' 772 run_adb_shell_cmd('am start' +\ 773 ' -n com.android.car.test.stressfs/.WritingActivity' +\ 774 ' -a com.android.car.test.stressfs.START') 775 # Give this app some time to start. 776 time.sleep(1) 777 if permissive: 778 run_adb_shell_cmd_as_root('setenforce 0') 779 780 retry = 0 781 while retry < 5: 782 if do_reboot(serial, use_adb_reboot): 783 break 784 retry += 1 785 786 print 'Waiting the device' 787 run_adb_cmd('wait-for-device') 788 789 if adb_buffersize is not None: 790 # increase the buffer size 791 if run_adb_cmd('logcat -G {}'.format(adb_buffersize)) != 0: 792 debug('Fail to set logcat buffer size as {}'.format(adb_buffersize)) 793 794def run_adb_cmd(cmd): 795 return subprocess.call(ADB_CMD + ' ' + cmd, shell=True) 796 797def run_adb_shell_cmd(cmd): 798 return subprocess.call(ADB_CMD + ' shell ' + cmd, shell=True) 799 800def run_adb_shell_cmd_as_root(cmd): 801 return subprocess.call(ADB_CMD + ' shell su root ' + cmd, shell=True) 802 803def logcat_time_func(offset_year): 804 def f(date_str): 805 ndate = datetime.datetime.strptime(str(offset_year) + '-' + 806 date_str, '%Y-%m-%d %H:%M:%S.%f') 807 return datetime_to_unix_time(ndate) 808 return f 809 810def datetime_to_unix_time(ndate): 811 return time.mktime(ndate.timetuple()) + ndate.microsecond/1000000.0 812 813def stddev(data): 814 items_count = len(data) 815 avg = sum(data) / items_count 816 sq_diffs_sum = sum([(v - avg) ** 2 for v in data]) 817 variance = sq_diffs_sum / items_count 818 return math.sqrt(variance) 819 820def grab_bootchart(boot_chart_file_name): 821 subprocess.call("./system/core/init/grab-bootchart.sh", shell=True) 822 print "Saving boot chart as " + boot_chart_file_name + ".tgz" 823 subprocess.call('cp /tmp/android-bootchart/bootchart.tgz ./' + boot_chart_file_name + '.tgz',\ 824 shell=True) 825 subprocess.call('cp ./bootchart.png ./' + boot_chart_file_name + '.png', shell=True) 826 827def grab_systrace(systrace_file_name): 828 trace_file = systrace_file_name + "_trace.txt" 829 with open(trace_file, 'w') as f: 830 f.write("TRACE:\n") 831 run_adb_shell_cmd_as_root("cat /d/tracing/trace >> " + trace_file) 832 html_file = systrace_file_name + ".html" 833 subprocess.call("./external/chromium-trace/systrace.py --from-file=" + trace_file + " -o " +\ 834 html_file, shell=True) 835 836if __name__ == '__main__': 837 main() 838