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