| #!/usr/bin/python |
| |
| # Copyright (C) 2016 The Android Open Source Project |
| # |
| # Licensed under the Apache License, Version 2.0 (the "License"); |
| # you may not use this file except in compliance with the License. |
| # You may obtain a copy of the License at |
| # |
| # http://www.apache.org/licenses/LICENSE-2.0 |
| # |
| # Unless required by applicable law or agreed to in writing, software |
| # distributed under the License is distributed on an "AS IS" BASIS, |
| # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
| # See the License for the specific language governing permissions and |
| # limitations under the License. |
| # |
| """Tool to analyze logcat and dmesg logs. |
| |
| bootanalyze read logcat and dmesg loga and determines key points for boot. |
| """ |
| |
| import argparse |
| import collections |
| import datetime |
| import math |
| import operator |
| import os |
| import re |
| import select |
| import subprocess |
| import sys |
| import time |
| import yaml |
| |
| from datetime import datetime, date |
| |
| |
| TIME_DMESG = "\[\s*(\d+\.\d+)\]" |
| TIME_LOGCAT = "[0-9]+\.?[0-9]*" |
| KERNEL_TIME_KEY = "kernel" |
| BOOT_ANIM_END_TIME_KEY = "BootAnimEnd" |
| KERNEL_BOOT_COMPLETE = "BootComplete_kernel" |
| LOGCAT_BOOT_COMPLETE = "BootComplete" |
| LAUNCHER_START = "LauncherStart" |
| BOOT_TIME_TOO_BIG = 200.0 |
| MAX_RETRIES = 5 |
| DEBUG = False |
| ADB_CMD = "adb" |
| TIMING_THRESHOLD = 5.0 |
| BOOT_PROP = "\[ro\.boottime\.([^\]]+)\]:\s+\[(\d+)\]" |
| BOOTLOADER_TIME_PROP = "\[ro\.boot\.boottime\]:\s+\[([^\]]+)\]" |
| |
| max_wait_time = BOOT_TIME_TOO_BIG |
| |
| def main(): |
| global ADB_CMD |
| |
| args = init_arguments() |
| |
| if args.iterate < 1: |
| raise Exception('Number of iteration must be >=1'); |
| |
| if args.iterate > 1 and not args.reboot: |
| print "Forcing reboot flag" |
| args.reboot = True |
| |
| if args.serial: |
| ADB_CMD = "%s %s" % ("adb -s", args.serial) |
| |
| error_time = BOOT_TIME_TOO_BIG * 10 |
| if args.errortime: |
| error_time = float(args.errortime) |
| if args.maxwaittime: |
| global max_wait_time |
| max_wait_time = float(args.maxwaittime) |
| |
| components_to_monitor = {} |
| if args.componentmonitor: |
| items = args.componentmonitor.split(",") |
| for item in items: |
| kv = item.split("=") |
| key = kv[0] |
| value = float(kv[1]) |
| components_to_monitor[key] = value |
| |
| cfg = yaml.load(args.config) |
| |
| if args.stressfs: |
| if run_adb_cmd('install -r -g ' + args.stressfs) != 0: |
| raise Exception('StressFS APK not installed'); |
| |
| if args.iterate > 1 and args.bootchart: |
| run_adb_shell_cmd_as_root('touch /data/bootchart/enabled') |
| |
| search_events = {key: re.compile(pattern) |
| for key, pattern in cfg['events'].iteritems()} |
| timing_events = {key: re.compile(pattern) |
| for key, pattern in cfg['timings'].iteritems()} |
| |
| data_points = {} |
| kernel_timing_points = collections.OrderedDict() |
| logcat_timing_points = collections.OrderedDict() |
| boottime_points = collections.OrderedDict() |
| boot_chart_file_name_prefix = "bootchart-" + datetime.now().strftime("%Y-%m-%d-%H-%M-%S") |
| systrace_file_name_prefix = "systrace-" + datetime.now().strftime("%Y-%m-%d-%H-%M-%S") |
| for it in range(0, args.iterate): |
| if args.iterate > 1: |
| print "Run: {0}".format(it) |
| attempt = 1 |
| processing_data = None |
| timings = None |
| boottime_events = None |
| while attempt <= MAX_RETRIES and processing_data is None: |
| attempt += 1 |
| processing_data, kernel_timings, logcat_timings, boottime_events = iterate( |
| args, search_events, timing_events, cfg, error_time, components_to_monitor) |
| |
| if not processing_data or not boottime_events: |
| # Processing error |
| print "Failed to collect valid samples for run {0}".format(it) |
| continue |
| if args.bootchart: |
| grab_bootchart(boot_chart_file_name_prefix + "_run_" + str(it)) |
| |
| if args.systrace: |
| grab_systrace(systrace_file_name_prefix + "_run_" + str(it)) |
| for k, v in processing_data.iteritems(): |
| if k not in data_points: |
| data_points[k] = [] |
| data_points[k].append(v['value']) |
| |
| if kernel_timings is not None: |
| for k, v in kernel_timings.iteritems(): |
| if k not in kernel_timing_points: |
| kernel_timing_points[k] = [] |
| kernel_timing_points[k].append(v) |
| if logcat_timings is not None: |
| for k, v in logcat_timings.iteritems(): |
| if k not in logcat_timing_points: |
| logcat_timing_points[k] = [] |
| logcat_timing_points[k].append(v) |
| |
| for k, v in boottime_events.iteritems(): |
| if not k in boottime_points: |
| boottime_points[k] = [] |
| boottime_points[k].append(v) |
| |
| if args.stressfs: |
| run_adb_cmd('uninstall com.android.car.test.stressfs') |
| run_adb_shell_cmd('"rm -rf /storage/emulated/0/stressfs_data*"') |
| |
| if args.iterate > 1: |
| print "-----------------" |
| print "ro.boottime.* after {0} runs".format(args.iterate) |
| print '{0:30}: {1:<7} {2:<7} {3}'.format("Event", "Mean", "stddev", "#runs") |
| for item in boottime_points.items(): |
| num_runs = len(item[1]) |
| print '{0:30}: {1:<7.5} {2:<7.5} {3} {4}'.format( |
| item[0], sum(item[1])/num_runs, stddev(item[1]),\ |
| "*time taken" if item[0].startswith("init.") else "",\ |
| num_runs if num_runs != args.iterate else "") |
| |
| if args.timings: |
| dump_timings_points_summary("Kernel", kernel_timing_points, args) |
| dump_timings_points_summary("Logcat", logcat_timing_points, args) |
| |
| |
| print "-----------------" |
| print "Avg values after {0} runs".format(args.iterate) |
| print '{0:30}: {1:<7} {2:<7} {3}'.format("Event", "Mean", "stddev", "#runs") |
| |
| average_with_stddev = [] |
| for item in data_points.items(): |
| average_with_stddev.append((item[0], sum(item[1])/len(item[1]), stddev(item[1]),\ |
| len(item[1]))) |
| for item in sorted(average_with_stddev, key=lambda entry: entry[1]): |
| print '{0:30}: {1:<7.5} {2:<7.5} {3}'.format( |
| item[0], item[1], item[2], item[3] if item[3] != args.iterate else "") |
| |
| run_adb_shell_cmd_as_root('rm /data/bootchart/enabled') |
| |
| |
| def dump_timings_points_summary(msg_header, timing_points, args): |
| averaged_timing_points = [] |
| for item in timing_points.items(): |
| average = sum(item[1])/len(item[1]) |
| std_dev = stddev(item[1]) |
| averaged_timing_points.append((item[0], average, std_dev, len(item[1]))) |
| |
| print "-----------------" |
| print msg_header + " timing in order, Avg time values after {0} runs".format(args.iterate) |
| print '{0:30}: {1:<7} {2:<7} {3}'.format("Event", "Mean", "stddev", "#runs") |
| for item in averaged_timing_points: |
| print '{0:30}: {1:<7.5} {2:<7.5} {3}'.format( |
| item[0], item[1], item[2], item[3] if item[3] != args.iterate else "") |
| |
| print "-----------------" |
| print msg_header + " timing top items, Avg time values after {0} runs".format(args.iterate) |
| print '{0:30}: {1:<7} {2:<7} {3}'.format("Event", "Mean", "stddev", "#runs") |
| for item in sorted(averaged_timing_points, key=lambda entry: entry[1], reverse=True): |
| if item[1] < TIMING_THRESHOLD: |
| break |
| print '{0:30}: {1:<7.5} {2:<7.5} {3}'.format( |
| item[0], item[1], item[2], item[3] if item[3] != args.iterate else "") |
| |
| def capture_bugreport(bugreport_hint, boot_complete_time): |
| now = datetime.now() |
| bugreport_file = ("bugreport-%s-" + bugreport_hint + "-%s.zip") \ |
| % (now.strftime("%Y-%m-%d-%H-%M-%S"), str(boot_complete_time)) |
| print "Boot up time too big, will capture bugreport %s" % (bugreport_file) |
| os.system(ADB_CMD + " bugreport " + bugreport_file) |
| |
| def generate_timing_points(timing_events, timings): |
| timing_points = collections.OrderedDict() |
| for k, l in timing_events.iteritems(): |
| for v in l: |
| name, time_v = extract_timing(v, timings) |
| if name and time_v: |
| if v.find("SystemServerTimingAsync") > 0: |
| name = "(" + name + ")" |
| new_name = name |
| name_index = 0 |
| while timing_points.get(new_name): # if the name is already taken, append #digit |
| name_index += 1 |
| new_name = name + "#" + str(name_index) |
| name = new_name |
| if k.endswith("_secs"): |
| timing_points[name] = time_v * 1000.0 |
| else: |
| timing_points[name] = time_v |
| return timing_points |
| |
| def dump_timing_points(msg_header, timing_points): |
| print msg_header + " event timing in time order, key: time" |
| for item in timing_points.items(): |
| print '{0:30}: {1:<7.5}'.format(item[0], item[1]) |
| print "-----------------" |
| print msg_header + " event timing top items" |
| for item in sorted(timing_points.items(), key=operator.itemgetter(1), reverse = True): |
| if item[1] < TIMING_THRESHOLD: |
| break |
| print '{0:30}: {1:<7.5}'.format( |
| item[0], item[1]) |
| print "-----------------" |
| |
| def iterate(args, search_events, timings, cfg, error_time, components_to_monitor): |
| if args.reboot: |
| reboot(args.serial, args.stressfs != '', args.permissive, args.adb_reboot) |
| |
| dmesg_events, kernel_timing_events = collect_events(search_events, ADB_CMD +\ |
| ' shell su root dmesg -w', timings,\ |
| [ KERNEL_BOOT_COMPLETE ], True) |
| |
| logcat_stop_events = [ LOGCAT_BOOT_COMPLETE, KERNEL_BOOT_COMPLETE, LAUNCHER_START] |
| if args.fs_check: |
| logcat_stop_events.append("FsStat") |
| logcat_events, logcat_timing_events = collect_events( |
| search_events, ADB_CMD + ' logcat -b all -v epoch', timings, logcat_stop_events, False) |
| logcat_event_time = extract_time( |
| logcat_events, TIME_LOGCAT, float); |
| logcat_original_time = extract_time( |
| logcat_events, TIME_LOGCAT, str); |
| dmesg_event_time = extract_time( |
| dmesg_events, TIME_DMESG, float); |
| boottime_events = fetch_boottime_property() |
| events = {} |
| diff_time = 0 |
| max_time = 0 |
| events_to_correct = [] |
| replaced_from_dmesg = set() |
| |
| time_correction_delta = 0 |
| time_correction_time = 0 |
| if ('time_correction_key' in cfg |
| and cfg['time_correction_key'] in logcat_events): |
| match = search_events[cfg['time_correction_key']].search( |
| logcat_events[cfg['time_correction_key']]) |
| if match and logcat_event_time[cfg['time_correction_key']]: |
| time_correction_delta = float(match.group(1)) |
| time_correction_time = logcat_event_time[cfg['time_correction_key']] |
| |
| debug("time_correction_delta = {0}, time_correction_time = {1}".format( |
| time_correction_delta, time_correction_time)) |
| |
| for k, v in logcat_event_time.iteritems(): |
| if v <= time_correction_time: |
| logcat_event_time[k] += time_correction_delta |
| v = v + time_correction_delta |
| debug("correcting event to event[{0}, {1}]".format(k, v)) |
| |
| if not logcat_event_time.get(KERNEL_TIME_KEY): |
| print "kernel time not captured in logcat, cannot get time diff" |
| return None, None, None, None |
| diffs = [] |
| diffs.append((logcat_event_time[KERNEL_TIME_KEY], logcat_event_time[KERNEL_TIME_KEY])) |
| if logcat_event_time.get(BOOT_ANIM_END_TIME_KEY) and dmesg_event_time.get(BOOT_ANIM_END_TIME_KEY): |
| diffs.append((logcat_event_time[BOOT_ANIM_END_TIME_KEY],\ |
| logcat_event_time[BOOT_ANIM_END_TIME_KEY] -\ |
| dmesg_event_time[BOOT_ANIM_END_TIME_KEY])) |
| if not dmesg_event_time.get(KERNEL_BOOT_COMPLETE): |
| print "BootAnimEnd time or BootComplete-kernel not captured in both log" +\ |
| ", cannot get time diff" |
| return None, None, None, None |
| diffs.append((logcat_event_time[KERNEL_BOOT_COMPLETE],\ |
| logcat_event_time[KERNEL_BOOT_COMPLETE] - dmesg_event_time[KERNEL_BOOT_COMPLETE])) |
| |
| for k, v in logcat_event_time.iteritems(): |
| debug("event[{0}, {1}]".format(k, v)) |
| events[k] = v |
| if k in dmesg_event_time: |
| debug("{0} is in dmesg".format(k)) |
| events[k] = dmesg_event_time[k] |
| replaced_from_dmesg.add(k) |
| else: |
| events_to_correct.append(k) |
| |
| diff_prev = diffs[0] |
| for k in events_to_correct: |
| diff = diffs[0] |
| while diff[0] < events[k] and len(diffs) > 1: |
| diffs.pop(0) |
| diff_prev = diff |
| diff = diffs[0] |
| events[k] = events[k] - diff[1] |
| if events[k] < 0.0: |
| if events[k] < -0.1: # maybe previous one is better fit |
| events[k] = events[k] + diff[1] - diff_prev[1] |
| else: |
| events[k] = 0.0 |
| |
| data_points = collections.OrderedDict() |
| |
| print "-----------------" |
| print "ro.boottime.*: time" |
| for item in boottime_events.items(): |
| print '{0:30}: {1:<7.5} {2}'.format(item[0], item[1],\ |
| "*time taken" if item[0].startswith("init.") else "") |
| print "-----------------" |
| |
| if args.timings: |
| kernel_timing_points = generate_timing_points(kernel_timing_events, timings) |
| logcat_timing_points = generate_timing_points(logcat_timing_events, timings) |
| dump_timing_points("Kernel", kernel_timing_points) |
| dump_timing_points("Logcat", logcat_timing_points) |
| |
| for item in sorted(events.items(), key=operator.itemgetter(1)): |
| data_points[item[0]] = { |
| 'value': item[1], |
| 'from_dmesg': item[0] in replaced_from_dmesg, |
| 'logcat_value': logcat_original_time[item[0]] |
| } |
| # add times with bootloader |
| if events.get("BootComplete") and boottime_events.get("bootloader"): |
| total = events["BootComplete"] + boottime_events["bootloader"] |
| data_points["*BootComplete+Bootloader"] = { |
| 'value': total, |
| 'from_dmesg': False, |
| 'logcat_value': 0.0 |
| } |
| if events.get("LauncherStart") and boottime_events.get("bootloader"): |
| total = events["LauncherStart"] + boottime_events["bootloader"] |
| data_points["*LauncherStart+Bootloader"] = { |
| 'value': total, |
| 'from_dmesg': False, |
| 'logcat_value': 0.0 |
| } |
| for k, v in data_points.iteritems(): |
| print '{0:30}: {1:<7.5} {2:1} ({3})'.format( |
| k, v['value'], '*' if v['from_dmesg'] else '', v['logcat_value']) |
| |
| print '\n* - event time was obtained from dmesg log\n' |
| |
| if events[LOGCAT_BOOT_COMPLETE] > error_time and not args.ignore: |
| capture_bugreport("bootuptoolong", events[LOGCAT_BOOT_COMPLETE]) |
| |
| for k, v in components_to_monitor.iteritems(): |
| logcat_value_measured = logcat_timing_points.get(k) |
| kernel_value_measured = kernel_timing_points.get(k) |
| data_from_data_points = data_points.get(k) |
| if logcat_value_measured and logcat_value_measured > v: |
| capture_bugreport(k + "-" + str(logcat_value_measured), events[LOGCAT_BOOT_COMPLETE]) |
| break |
| elif kernel_value_measured and kernel_value_measured > v: |
| capture_bugreport(k + "-" + str(kernel_value_measured), events[LOGCAT_BOOT_COMPLETE]) |
| break |
| elif data_from_data_points and data_from_data_points['value'] * 1000.0 > v: |
| capture_bugreport(k + "-" + str(data_from_data_points['value']), events[LOGCAT_BOOT_COMPLETE]) |
| break |
| |
| if args.fs_check: |
| fs_stat = None |
| if logcat_events.get("FsStat"): |
| fs_stat_pattern = cfg["events"]["FsStat"] |
| m = re.search(fs_stat_pattern, logcat_events.get("FsStat")) |
| if m: |
| fs_stat = m.group(1) |
| print 'fs_stat:', fs_stat |
| |
| if fs_stat: |
| fs_stat_val = int(fs_stat, 0) |
| if (fs_stat_val & ~0x17) != 0: |
| capture_bugreport("fs_stat_" + fs_stat, events[LOGCAT_BOOT_COMPLETE]) |
| |
| return data_points, kernel_timing_points, logcat_timing_points, boottime_events |
| |
| def debug(string): |
| if DEBUG: |
| print string |
| |
| def extract_timing(s, patterns): |
| for k, p in patterns.iteritems(): |
| m = p.search(s) |
| if m: |
| g_dict = m.groupdict() |
| return g_dict['name'], float(g_dict['time']) |
| return None, None |
| |
| def init_arguments(): |
| parser = argparse.ArgumentParser(description='Measures boot time.') |
| parser.add_argument('-r', '--reboot', dest='reboot', |
| action='store_true', |
| help='reboot device for measurement', ) |
| parser.add_argument('-c', '--config', dest='config', |
| default='config.yaml', type=argparse.FileType('r'), |
| help='config file for the tool', ) |
| parser.add_argument('-s', '--stressfs', dest='stressfs', |
| default='', type=str, |
| help='APK file for the stressfs tool used to write to the data partition ' +\ |
| 'during shutdown') |
| parser.add_argument('-n', '--iterate', dest='iterate', type=int, default=1, |
| help='number of time to repeat the measurement', ) |
| parser.add_argument('-g', '--ignore', dest='ignore', action='store_true', |
| help='ignore too big values error', ) |
| parser.add_argument('-t', '--timings', dest='timings', action='store_true', |
| help='print individual component times', default=True, ) |
| parser.add_argument('-p', '--serial', dest='serial', action='store', |
| help='android device serial number') |
| parser.add_argument('-e', '--errortime', dest='errortime', action='store', |
| help='handle bootup time bigger than this as error') |
| parser.add_argument('-w', '--maxwaittime', dest='maxwaittime', action='store', |
| help='wait for up to this time to collect logs. Retry after this time.' +\ |
| ' Default is 200 sec.') |
| parser.add_argument('-f', '--fs_check', dest='fs_check', |
| action='store_true', |
| help='check fs_stat after reboot', ) |
| parser.add_argument('-a', '--adb_reboot', dest='adb_reboot', |
| action='store_true', |
| help='reboot with adb reboot', ) |
| parser.add_argument('-v', '--permissive', dest='permissive', |
| action='store_true', |
| help='set selinux into permissive before reboot', ) |
| parser.add_argument('-m', '--componentmonitor', dest='componentmonitor', action='store', |
| help='capture bugreport if specified timing component is taking more than ' +\ |
| 'certain time. Unlike errortime, the result will not be rejected in' +\ |
| 'averaging. Format is key1=time1,key2=time2...') |
| parser.add_argument('-b', '--bootchart', dest='bootchart', |
| action='store_true', |
| help='collect bootchart from the device.', ) |
| parser.add_argument('-y', '--systrace', dest='systrace', |
| action='store_true', |
| help='collect systrace from the device. kernel trace should be already enabled', ) |
| return parser.parse_args() |
| |
| def handle_zygote_event(zygote_pids, events, event, line): |
| words = line.split() |
| if len(words) > 1: |
| pid = int(words[1]) |
| if len(zygote_pids) == 2: |
| if pid == zygote_pids[1]: # secondary |
| event = event + "-secondary" |
| elif len(zygote_pids) == 1: |
| if zygote_pids[0] != pid: # new pid, need to decide if old ones were secondary |
| primary_pid = min(pid, zygote_pids[0]) |
| secondary_pid = max(pid, zygote_pids[0]) |
| zygote_pids.pop() |
| zygote_pids.append(primary_pid) |
| zygote_pids.append(secondary_pid) |
| if pid == primary_pid: # old one was secondary: |
| move_to_secondary = [] |
| for k, l in events.iteritems(): |
| if k.startswith("zygote"): |
| move_to_secondary.append((k, l)) |
| for item in move_to_secondary: |
| del events[item[0]] |
| if item[0].endswith("-secondary"): |
| print "Secondary already exists for event %s while found new pid %d, primary %d "\ |
| % (item[0], secondary_pid, primary_pid) |
| else: |
| events[item[0] + "-secondary"] = item[1] |
| else: |
| event = event + "-secondary" |
| else: |
| zygote_pids.append(pid) |
| events[event] = line |
| |
| def update_name_if_already_exist(events, name): |
| existing_event = events.get(name) |
| i = 0 |
| new_name = name |
| while existing_event: |
| i += 1 |
| new_name = name + "_" + str(i) |
| existing_event = events.get(new_name) |
| return new_name |
| |
| def collect_events(search_events, command, timings, stop_events, disable_timing_after_zygote): |
| events = collections.OrderedDict() |
| timing_events = {} |
| process = subprocess.Popen(command, shell=True, |
| stdout=subprocess.PIPE); |
| data_available = stop_events is None |
| zygote_pids = [] |
| start_time = time.time() |
| zygote_found = False |
| |
| line = None |
| read_poll = select.poll() |
| read_poll.register(process.stdout, select.POLLIN) |
| while True: |
| time_left = start_time + max_wait_time - time.time() |
| if time_left <= 0: |
| print "timeout waiting for event, continue", time_left |
| break |
| read_r = read_poll.poll(time_left * 1000.0) |
| if read_r: |
| line = process.stdout.readline() |
| else: |
| print "poll timeout waiting for event, continue", time_left |
| break |
| if not data_available: |
| print "Collecting data samples from '%s'. Please wait...\n" % command |
| data_available = True |
| event = get_boot_event(line, search_events); |
| if event: |
| debug("event[{0}] captured: {1}".format(event, line)) |
| if event == "starting_zygote": |
| events[event] = line |
| zygote_found = True |
| elif event.startswith("zygote"): |
| handle_zygote_event(zygote_pids, events, event, line) |
| else: |
| new_event = update_name_if_already_exist(events, event) |
| events[new_event] = line |
| if event in stop_events: |
| stop_events.remove(event) |
| print "remaining stop_events:", stop_events |
| if len(stop_events) == 0: |
| break; |
| |
| timing_event = get_boot_event(line, timings); |
| if timing_event and (not disable_timing_after_zygote or not zygote_found): |
| if timing_event not in timing_events: |
| timing_events[timing_event] = [] |
| timing_events[timing_event].append(line) |
| debug("timing_event[{0}] captured: {1}".format(timing_event, line)) |
| |
| process.terminate() |
| return events, timing_events |
| |
| def fetch_boottime_property(): |
| cmd = ADB_CMD + ' shell su root getprop' |
| events = {} |
| process = subprocess.Popen(cmd, shell=True, |
| stdout=subprocess.PIPE); |
| out = process.stdout |
| pattern = re.compile(BOOT_PROP) |
| pattern_bootloader = re.compile(BOOTLOADER_TIME_PROP) |
| bootloader_time = 0.0 |
| for line in out: |
| match = pattern.match(line) |
| if match: |
| if match.group(1).startswith("init."): |
| events[match.group(1)] = float(match.group(2)) / 1000.0 #ms to s |
| else: |
| events[match.group(1)] = float(match.group(2)) / 1000000000.0 #ns to s |
| match = pattern_bootloader.match(line) |
| if match: |
| items = match.group(1).split(",") |
| for item in items: |
| entry_pair = item.split(":") |
| entry_name = entry_pair[0] |
| time_spent = float(entry_pair[1]) / 1000 #ms to s |
| if entry_name != "SW": |
| bootloader_time = bootloader_time + time_spent |
| ordered_event = collections.OrderedDict() |
| if bootloader_time != 0.0: |
| ordered_event["bootloader"] = bootloader_time; |
| for item in sorted(events.items(), key=operator.itemgetter(1)): |
| ordered_event[item[0]] = item[1] |
| return ordered_event |
| |
| |
| def get_boot_event(line, events): |
| for event_key, event_pattern in events.iteritems(): |
| if event_pattern.search(line): |
| return event_key |
| return None |
| |
| def extract_a_time(line, pattern, date_transform_function): |
| found = re.findall(pattern, line) |
| if len(found) > 0: |
| return date_transform_function(found[0]) |
| else: |
| return None |
| |
| def extract_time(events, pattern, date_transform_function): |
| result = collections.OrderedDict() |
| for event, data in events.iteritems(): |
| time = extract_a_time(data, pattern, date_transform_function) |
| if time: |
| result[event] = time |
| else: |
| print "Failed to find time for event: ", event, data |
| return result |
| |
| |
| def do_reboot(serial, use_adb_reboot): |
| original_devices = subprocess.check_output("adb devices", shell=True) |
| if use_adb_reboot: |
| print 'Rebooting the device using adb reboot' |
| run_adb_cmd('reboot') |
| else: |
| print 'Rebooting the device using svc power reboot' |
| run_adb_shell_cmd_as_root('svc power reboot') |
| # Wait for the device to go away |
| retry = 0 |
| while retry < 20: |
| current_devices = subprocess.check_output("adb devices", shell=True) |
| if original_devices != current_devices: |
| if not serial or (serial and current_devices.find(serial) < 0): |
| return True |
| time.sleep(1) |
| retry += 1 |
| return False |
| |
| def reboot(serial, use_stressfs, permissive, use_adb_reboot): |
| if use_stressfs: |
| print 'Starting write to data partition' |
| run_adb_shell_cmd('am start' +\ |
| ' -n com.android.car.test.stressfs/.WritingActivity' +\ |
| ' -a com.android.car.test.stressfs.START') |
| # Give this app some time to start. |
| time.sleep(1) |
| if permissive: |
| run_adb_shell_cmd_as_root('setenforce 0') |
| |
| retry = 0 |
| while retry < 5: |
| if do_reboot(serial, use_adb_reboot): |
| break |
| retry += 1 |
| |
| print 'Waiting the device' |
| run_adb_cmd('wait-for-device') |
| |
| def run_adb_cmd(cmd): |
| return subprocess.call(ADB_CMD + ' ' + cmd, shell=True) |
| |
| def run_adb_shell_cmd(cmd): |
| return subprocess.call(ADB_CMD + ' shell ' + cmd, shell=True) |
| |
| def run_adb_shell_cmd_as_root(cmd): |
| return subprocess.call(ADB_CMD + ' shell su root ' + cmd, shell=True) |
| |
| def logcat_time_func(offset_year): |
| def f(date_str): |
| ndate = datetime.datetime.strptime(str(offset_year) + '-' + |
| date_str, '%Y-%m-%d %H:%M:%S.%f') |
| return datetime_to_unix_time(ndate) |
| return f |
| |
| def datetime_to_unix_time(ndate): |
| return time.mktime(ndate.timetuple()) + ndate.microsecond/1000000.0 |
| |
| def stddev(data): |
| items_count = len(data) |
| avg = sum(data) / items_count |
| sq_diffs_sum = sum([(v - avg) ** 2 for v in data]) |
| variance = sq_diffs_sum / items_count |
| return math.sqrt(variance) |
| |
| def grab_bootchart(boot_chart_file_name): |
| subprocess.call("./system/core/init/grab-bootchart.sh", shell=True) |
| print "Saving boot chart as " + boot_chart_file_name + ".tgz" |
| subprocess.call('cp /tmp/android-bootchart/bootchart.tgz ./' + boot_chart_file_name + '.tgz',\ |
| shell=True) |
| subprocess.call('cp ./bootchart.png ./' + boot_chart_file_name + '.png', shell=True) |
| |
| def grab_systrace(systrace_file_name): |
| trace_file = systrace_file_name + "_trace.txt" |
| with open(trace_file, 'w') as f: |
| f.write("TRACE:\n") |
| run_adb_shell_cmd_as_root("cat /d/tracing/trace >> " + trace_file) |
| html_file = systrace_file_name + ".html" |
| subprocess.call("./external/chromium-trace/systrace.py --from-file=" + trace_file + " -o " +\ |
| html_file, shell=True) |
| |
| if __name__ == '__main__': |
| main() |
