diff options
author | Wei Wang <wvw@google.com> | 2018-03-23 11:28:59 -0700 |
---|---|---|
committer | Wei Wang <wvw@google.com> | 2018-03-23 11:28:59 -0700 |
commit | bbf73e5412c44e643a7b751f24099cd3891adfc3 (patch) | |
tree | 7e4d0fa8f0ec93e8fbfc31833d2bddb7eef93d48 /boottime_tools | |
parent | 56f68caff62f404cff5491b3e84e3d031781db32 (diff) | |
download | extras-bbf73e5412c44e643a7b751f24099cd3891adfc3.tar.gz |
Move boottime tools to system folder
Bug: 65481007
Test: Build
Change-Id: I66b280ff4fe06b47084ce4279705582e3d4d0330
Diffstat (limited to 'boottime_tools')
21 files changed, 2402 insertions, 0 deletions
diff --git a/boottime_tools/bootanalyze/Android.mk b/boottime_tools/bootanalyze/Android.mk new file mode 100644 index 00000000..5df0dd83 --- /dev/null +++ b/boottime_tools/bootanalyze/Android.mk @@ -0,0 +1,20 @@ +# Copyright (C) 2017 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. +# +# + +LOCAL_PATH := $(call my-dir) + +# Include the sub-makefiles +include $(call all-makefiles-under,$(LOCAL_PATH)) diff --git a/boottime_tools/bootanalyze/README.md b/boottime_tools/bootanalyze/README.md new file mode 100644 index 00000000..d6e0412f --- /dev/null +++ b/boottime_tools/bootanalyze/README.md @@ -0,0 +1,15 @@ +# bootanalyze # + +The bootanalyze tool helps to profile boot timing. + +Per specific product modify config.yaml file to include +events you are looking for. Config should look like: + + stop_event: <logcat log message which will terminate log collection after reboot> + events: + event1_name: <pattern that matches log message> + event2_..... + +On some devise clock is showing incorrect time for first couple of seconds after boot. +To ensure correct adjustment of time, one has to include event in config that will +be present in dmesg log after clock correction. diff --git a/boottime_tools/bootanalyze/bootanalyze.py b/boottime_tools/bootanalyze/bootanalyze.py new file mode 100755 index 00000000..b8783585 --- /dev/null +++ b/boottime_tools/bootanalyze/bootanalyze.py @@ -0,0 +1,818 @@ +#!/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 threading +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_pattern = {key: re.compile(pattern) + for key, pattern in cfg['events'].iteritems()} + timing_events_pattern = {key: re.compile(pattern) + for key, pattern in cfg['timings'].iteritems()} + shutdown_events_pattern = {key: re.compile(pattern) + for key, pattern in cfg['shutdown_events'].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") + shutdown_event_all = collections.OrderedDict() + shutdown_timing_event_all = collections.OrderedDict() + 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, shutdown_events,\ + shutdown_timing_events = iterate(\ + args, search_events_pattern, timing_events_pattern, shutdown_events_pattern, cfg,\ + error_time, components_to_monitor) + if shutdown_events: + for k, v in shutdown_events.iteritems(): + events = shutdown_event_all.get(k) + if not events: + events = [] + shutdown_event_all[k] = events + events.append(v) + if shutdown_timing_events: + for k, v in shutdown_timing_events.iteritems(): + events = shutdown_timing_event_all.get(k) + if not events: + events = [] + shutdown_timing_event_all[k] = events + events.append(v) + 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 "\nshutdown events after {0} runs".format(args.iterate) + print '{0:30}: {1:<7} {2:<7} {3}'.format("Event", "Mean", "stddev", "#runs") + for item in shutdown_event_all.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 "") + print "\nshutdown timing events after {0} runs".format(args.iterate) + print '{0:30}: {1:<7} {2:<7} {3}'.format("Event", "Mean", "stddev", "#runs") + for item in shutdown_timing_event_all.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 "") + + 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 handle_reboot_log(capture_log_on_error, shutdown_events_pattern, components_to_monitor): + shutdown_events, shutdown_timing_events = collect_logcat_for_shutdown(capture_log_on_error,\ + shutdown_events_pattern, components_to_monitor) + print "\nshutdown events: time" + for item in shutdown_events.items(): + print '{0:30}: {1:<7.5}'.format(item[0], item[1]) + print "\nshutdown timing events: time" + for item in shutdown_timing_events.items(): + print '{0:30}: {1:<7.5}'.format(item[0], item[1]) + return shutdown_events, shutdown_timing_events + +def iterate(args, search_events_pattern, timings_pattern, shutdown_events_pattern, cfg, error_time,\ + components_to_monitor): + shutdown_events = None + shutdown_timing_events = None + if args.reboot: + # sleep to make sure that logcat reader is reading before adb is gone by reboot. ugly but make + # impl simple. + t = threading.Thread(target = lambda : (time.sleep(2), reboot(args.serial, args.stressfs != '',\ + args.permissive, args.adb_reboot))) + t.start() + shutdown_events, shutdown_timing_events = handle_reboot_log(True, shutdown_events_pattern,\ + components_to_monitor) + t.join() + + dmesg_events, kernel_timing_events = collect_events(search_events_pattern, ADB_CMD +\ + ' shell su root dmesg -w', timings_pattern,\ + [ 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_pattern, ADB_CMD + ' logcat -b all -v epoch', timings_pattern,\ + 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_pattern) + logcat_timing_points = generate_timing_points(logcat_timing_events, timings_pattern) + 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, shutdown_events,\ + shutdown_timing_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_logcat_for_shutdown(capture_log_on_error, shutdown_events_pattern,\ + log_capture_conditions): + events = collections.OrderedDict() + # shutdown does not have timing_events but calculated from checking Xyz - XyzDone / XyzTimeout + timing_events = collections.OrderedDict() + process = subprocess.Popen(ADB_CMD + ' logcat -b all -v epoch', shell=True, + stdout=subprocess.PIPE); + lines = [] + capture_log = False + shutdown_start_time = 0 + while (True): + line = process.stdout.readline().lstrip().rstrip() + if not line: + break + lines.append(line) + event = get_boot_event(line, shutdown_events_pattern); + if not event: + continue + time = extract_a_time(line, TIME_LOGCAT, float) + if not time: + print "cannot get time from: " + line + continue + if shutdown_start_time == 0: + shutdown_start_time = time + time = time - shutdown_start_time + events[event] = time + time_limit1 = log_capture_conditions.get(event) + if time_limit1 and time_limit1 <= time: + capture_log = True + pair_event = None + if event.endswith('Done'): + pair_event = event[:-4] + elif event.endswith('Timeout'): + pair_event = event[:-7] + if capture_log_on_error: + capture_log = True + if not pair_event: + continue + start_time = events.get(pair_event) + if not start_time: + print "No start event for " + event + continue + time_spent = time - start_time + timing_event_name = pair_event + "Duration" + timing_events[timing_event_name] = time_spent + time_limit2 = log_capture_conditions.get(timing_event_name) + if time_limit2 and time_limit2 <= time_spent: + capture_log = True + + if capture_log: + now = datetime.now() + log_file = ("shutdownlog-error-%s.txt") % (now.strftime("%Y-%m-%d-%H-%M-%S")) + print "Shutdown error, capture log to %s" % (log_file) + with open(log_file, 'w') as f: + f.write('\n'.join(lines)) + return events, timing_events + + +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 len(read_r) > 0 and read_r[0][1] == select.POLLIN: + 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() diff --git a/boottime_tools/bootanalyze/bugreport_anayze.py b/boottime_tools/bootanalyze/bugreport_anayze.py new file mode 100644 index 00000000..2575ebf6 --- /dev/null +++ b/boottime_tools/bootanalyze/bugreport_anayze.py @@ -0,0 +1,386 @@ +#!/usr/bin/python + +# Copyright (C) 2017 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 boot-up time from bugreport.""" + +import argparse +import collections +import datetime +import math +import operator +import os +import re +import select +import subprocess +import sys +import time +import threading +import yaml + +from datetime import datetime, date + +DBG = True + +LOG_START_PATTERN = r"""\-\-\-\-\-\-\s(.*)\s\-\-\-\-\-\-""" +LOG_END_PATTERN = r"""\-\-\-\-\-\-\s\S.*\s\-\-\-\-\-\-""" + +KERNEL_LOG_TITLE = "KERNEL LOG" +SYSYEM_LOG_TITLE = "SYSTEM LOG" +LAST_KMSG_TITLE = "LAST KMSG" +LAST_LOGCAT_TITLE = "LAST LOGCAT" + +SYSTEM_PROPS_TITLE = "SYSTEM PROPERTIES" + +TIME_DMESG = "\[\s*(\d+\.\d+)\]" +TIME_LOGCAT = "(\d+)\-(\d+)\s(\d+):(\d+):(\d+\.\d+)" + +NATIVE_CRASH_START_PATTERN = "I\sDEBUG\s+:\s\*\*\*\s\*\*\*" +NATIVE_CRASH_PATTERN = "I\sDEBUG\s+:" +JAVA_CRASH_START_PATTERN = "E\sAndroidRuntime:\sFATAL\sEXCEPTION" +JAVA_CRASH_PATTERN = "E\sAndroidRuntime:\s" + +EPOCH = datetime.utcfromtimestamp(0) + +def init_arguments(): + parser = argparse.ArgumentParser(description='Measures boot time from bugreport.') + parser.add_argument('-c', '--config', dest='config', + default='config.yaml', type=argparse.FileType('r'), + help='config file for the tool') + parser.add_argument('bugreport_file', nargs=1, help='bugreport txt file', + type=argparse.FileType('r')) + parser.add_argument('-n', '--iterate', dest='iterate', type=int, default=1, + help='number of time to repeat the measurement', ) + return parser.parse_args() + +# Event per each reboot, for distinghishing current boot from last boot +class Events: + def __init__(self): + self.events = collections.OrderedDict() #K: keyword, V:time in ms + self.timings = collections.OrderedDict() + self.shutdown_events = collections.OrderedDict() + self.java_crash = collections.OrderedDict() #K:time, V:list of crash infos, each entry per line + self.native_crash = collections.OrderedDict() + + def reset_events_time(self, delta): + new_events = collections.OrderedDict() + for entry in self.events.iteritems(): + new_events[entry[0]] = entry[1] - delta + self.events = new_events + if len(self.native_crash) > 0: + new_crash = collections.OrderedDict() + for entry in self.native_crash.iteritems(): + new_crash[entry[0] - delta] = entry[1] + self.native_crash = new_crash + if len(self.java_crash) > 0: + new_crash = collections.OrderedDict() + for entry in self.java_crash.iteritems(): + new_crash[entry[0] - delta] = entry[1] + self.java_crash = new_crash + + def reset_shutdown_events_time(self): + if len(self.shutdown_events) == 0: + return + time_offset = 0 + new_events = collections.OrderedDict() + for entry in self.shutdown_events.iteritems(): + if time_offset == 0: + time_offset = entry[1] + new_events[entry[0]] = entry[1] - time_offset + self.shutdown_events = new_events + + def dump_dict(self, d): + for entry in d.iteritems(): + print ' {0:30}: {1}'.format(entry[0], entry[1]) + + def dump_crash(self, time, stack): + print " Crash time:", time, " stack:" + print ' '.join(stack) + + def dump(self): + if len(self.events) > 0: + print "\n***Events:" + self.dump_dict(self.events) + if len(self.timings) > 0: + print "\n***Timings top 20" + timings_sorted = sorted(self.timings.items(), key = lambda item: item[1], reverse=True) + nums_to_dump = min(20, len(timings_sorted)) + for i in range(nums_to_dump): + print ' {0:30}: {1}'.format(timings_sorted[i][0], timings_sorted[i][1]) + print "\n***Timings:" + self.dump_dict(self.timings) + if len(self.shutdown_events) > 0: + print "\n***Shutdown Events (time relative to the begining of shutdown) :" + self.dump_dict(self.shutdown_events) + if len(self.native_crash) > 0: + print "\n***Native crash founds:", len(self.native_crash) + for entry in self.native_crash.iteritems(): + self.dump_crash(entry[0], entry[1]) + if len(self.java_crash) > 0: + print "\n***Java crash founds:", len(self.java_crash) + for entry in self.java_crash.iteritems(): + self.dump_crash(entry[0], entry[1]) + +class Parser: + def __init__(self, config_file, bugreport_file): + self.re_log_start = re.compile(LOG_START_PATTERN) + self.re_log_end = re.compile(LOG_END_PATTERN) + self.f = bugreport_file + cfg = yaml.load(config_file) + self.event_patterns = {key: re.compile(pattern) + for key, pattern in cfg['events'].iteritems()} + self.timing_patterns = {key: re.compile(pattern) + for key, pattern in cfg['timings'].iteritems()} + self.shutdown_event_patterns = {key: re.compile(pattern) + for key, pattern in cfg['shutdown_events'].iteritems()} + self.current_boot_kernel = Events() + self.current_boot_logcat = Events() + self.last_boot_kernel = Events() + self.last_boot_logcat = Events() + self.boottime_props = collections.OrderedDict() # K:prop, V:boot time, added in boot time order + self.bootloader_time = 0 + self.re_time_dmesg = re.compile(TIME_DMESG) + self.re_time_logcat = re.compile(TIME_LOGCAT) + self.re_native_crash_start = re.compile(NATIVE_CRASH_START_PATTERN) + self.re_native_crash = re.compile(NATIVE_CRASH_PATTERN) + self.re_java_crash_start = re.compile(JAVA_CRASH_START_PATTERN) + self.re_java_crash = re.compile(JAVA_CRASH_PATTERN) + + def match_an_event(self, event_patterns, line): + for event_key, event_pattern in event_patterns.iteritems(): + m = event_pattern.search(line) + if m: + return event_key, m + return None, None + + def get_event_time(self, line, is_kernel): + if is_kernel: + m = self.re_time_dmesg.search(line) + if not m: + print "Cannot get time from log:", line + return -1 + return int(float(m.group(1)) * 1000) + else: + m = self.re_time_logcat.search(line) + if not m: + print "Cannot get time from log:", line + return -1 + mm = int(m.group(1)) + dd = int(m.group(2)) + hh = int(m.group(3)) + min = int(m.group(4)) + usecs = int(float(m.group(5)) * 1000000) + secs = usecs / 1000000 + usecs = usecs - 1000000 * secs + dt = datetime(2017, mm, dd, hh, min, secs, usecs) + return int((dt - EPOCH).total_seconds() * 1000) + + def queue_crash(self, event, crash_time, crash_stacks, is_native_crash): + stacks = list(crash_stacks) + if is_native_crash: + event.native_crash[crash_time] = stacks + else: + event.java_crash[crash_time] = stacks + + def check_crash(self, event, orig_line): + line = orig_line + crash_time = 0 + crash_stacks = [] + is_native_crash = True + while len(line) > 0: + m = self.re_native_crash_start.search(line) + if m: + if len(crash_stacks) > 0: + self.queue_crash(event, crash_time, crash_stacks, is_native_crash) + crash_stacks = [] + is_native_crash = True + crash_stacks.append(line) + crash_time = self.get_event_time(line, False) + line = self.f.readline() + continue + m = self.re_native_crash.search(line) + if m: + crash_stacks.append(line) + line = self.f.readline() + continue + m = self.re_java_crash_start.search(line) + if m: + if len(crash_stacks) > 0: + self.queue_crash(event, crash_time, crash_stacks, is_native_crash) + crash_stacks = [] + is_native_crash = False + crash_stacks.append(line) + crash_time = self.get_event_time(line, False) + line = self.f.readline() + continue + m = self.re_java_crash.search(line) + if m: + crash_stacks.append(line) + line = self.f.readline() + continue + # reaching here means not crash, so return new line + if line != orig_line: + return line + else: + return self.f.readline() + + + + def handle_events(self, event, is_kernel): + line = self.f.readline() + while len(line) > 0 and not self.re_log_end.match(line): + key, m = self.match_an_event(self.event_patterns, line) + if m: + event.events[key] = self.get_event_time(line, is_kernel) + line = self.f.readline() + continue + key, m = self.match_an_event(self.timing_patterns, line) + if m: + name = m.group('name') + time = float(m.group('time')) + if key.endswith('_secs'): + time = time * 1000 + event.timings[name] = int(time) + line = self.f.readline() + continue + key, m = self.match_an_event(self.shutdown_event_patterns, line) + if m: + event.shutdown_events[key] = self.get_event_time(line, is_kernel) + line = self.f.readline() + continue + if not is_kernel: # collect crash + line = self.check_crash(event, line) + continue + line = self.f.readline() + + def handle_kernel_log(self): + if DBG: + print "start " + KERNEL_LOG_TITLE + self.handle_events(self.current_boot_kernel, True) + + def handle_system_log(self): + if DBG: + print "start " + SYSYEM_LOG_TITLE + self.handle_events(self.current_boot_logcat, False) + + def handle_last_kernel_log(self): + if DBG: + print "start " + LAST_KMSG_TITLE + self.handle_events(self.last_boot_kernel, True) + + def handle_last_system_log(self): + if DBG: + print "start " + LAST_LOGCAT_TITLE + self.handle_events(self.last_boot_logcat, False) + + def handle_system_props(self): + if DBG: + print "start " + SYSTEM_PROPS_TITLE + re_prop = re.compile(r"""\[(.+)\].*\[(.*)\]""") + RO_BOOTTIME_PROP = "ro.boottime." + boottime_props = {} # K: prop name, V: boot time in ms + line = self.f.readline() + while len(line) > 0 and not self.re_log_end.match(line): + m = re_prop.match(line) + if not m: + print "Cannot parse prop:", line + line = self.f.readline() + continue + if m.group(1).startswith(RO_BOOTTIME_PROP): + name = m.group(1)[len(RO_BOOTTIME_PROP):] + time = int(m.group(2)) / 1000000 # ns to ms + boottime_props[name] = time + elif m.group(1) == "ro.boot.boottime": + print "Found bootloader boottime ", line + entries = m.group(2).split(",") + for entry in entries: + values = entry.split(":") + if values[0] != "SW": + self.bootloader_time += int(values[1]) + line = self.f.readline() + self.boottime_props = collections.OrderedDict(sorted( + boottime_props.items(), key = lambda item: item[1])) + + def parse(self): + while (True): + l = self.f.readline() + if len(l) == 0: # EOF + return + m = self.re_log_start.match(l) + if not m: + continue + #print m.group(1) + if m.group(1).startswith(KERNEL_LOG_TITLE): + self.handle_kernel_log() + elif m.group(1).startswith(SYSYEM_LOG_TITLE): + self.handle_system_log() + elif m.group(1).startswith(SYSTEM_PROPS_TITLE): + self.handle_system_props() + elif m.group(1).startswith(LAST_KMSG_TITLE): + self.handle_last_kernel_log() + elif m.group(1).startswith(LAST_LOGCAT_TITLE): + self.handle_last_system_log() + + def dump_props(self): + if self.bootloader_time != 0: + print "*bootloader time:", self.bootloader_time + if self.boottime_props: + print "*ro.boottime.*:" + for name, t in self.boottime_props.iteritems(): + print ' {0:30}: {1}'.format(name, t) + + def reset_event_times(self, kernel_event, logcat_event): + has_boot_complete = True + kernel_bootcomplete_time = kernel_event.events.get("BootComplete_kernel") + if not kernel_bootcomplete_time: + has_boot_complete = False + logcat_bootcomplete_time = logcat_event.events.get("BootComplete") + if not logcat_bootcomplete_time: + has_boot_complete = False + time_delta = 0 + if has_boot_complete: + time_delta = logcat_bootcomplete_time - kernel_bootcomplete_time + else: + time_delta = logcat_event.events.values()[0] if len(logcat_event.events) > 0 else 0 + logcat_event.reset_events_time(time_delta) + logcat_event.reset_shutdown_events_time() + kernel_event.reset_shutdown_events_time() + return has_boot_complete + + def dump(self): + self.dump_props() + boot_complete_found = self.reset_event_times(self.current_boot_kernel, self.current_boot_logcat) + print "* Kernel dmesg:" + self.current_boot_kernel.dump() + print "\n\n* Logcat " + ("(time matched with kernel dmesg):" if boot_complete_found\ + else "(time set relative to the first event):") + self.current_boot_logcat.dump() + print "\n\n\n==== Data from last boot ===" + boot_complete_found = self.reset_event_times(self.last_boot_kernel, self.last_boot_logcat) + print "\n\n* Last Kernel dmesg:" + self.last_boot_kernel.dump() + print "\n\n* Last Logcat " + ("(time matched with kernel dmesg):" if boot_complete_found \ + else "(time set relative to the first event):") + self.last_boot_logcat.dump() + +def main(): + args = init_arguments() + + parser = Parser(args.config, args.bugreport_file[0]) + parser.parse() + parser.dump() + +if __name__ == '__main__': + main() diff --git a/boottime_tools/bootanalyze/config.yaml b/boottime_tools/bootanalyze/config.yaml new file mode 100644 index 00000000..37f2891b --- /dev/null +++ b/boottime_tools/bootanalyze/config.yaml @@ -0,0 +1,78 @@ +#YAML +time_correction_key: correction +timings: + system_server: SystemServerTiming(Async)?\s*:\s*(?P<name>\S+) took to complete:\s(?P<time>[0-9]+)ms + fs_shutdown: (?P<name>boot_fs_shutdown),(?P<time>[0-9]+),([0-9]+) + ueventd_secs: ueventd:\s(?P<name>\S.+)\stook\s(?P<time>[.0-9]+)\sseconds + init_command_ms: init:\sCommand\s(?P<name>\S.+)\sreturned.*took\s(?P<time>[.0-9]+)ms + init_service_exec_secs: init:\sService\s.*exec\s\S+\s\((?P<name>\S.+)\).*pid.*\swaiting\stook\s(?P<time>[.0-9]+)\sseconds + zygote64_timing: (?P<name>Zygote64Timing\:\s\S+)\stook\sto\scomplete\:\s(?P<time>[0-9]+)ms + zygote32_timing: (?P<name>Zygote32Timing\:\s\S+)\stook\sto\scomplete\:\s(?P<time>[0-9]+)ms +events: + kernel: Linux version + android_init_1st_stage: init first stage started + android_init_2st_stage: init second stage started + late_init: processing action \(late-init\) + fs: processing action \(fs\) + post-fs: processing action \(post-fs\) + late-fs: processing action \(late-fs\) + post-fs-data: processing action \(post-fs-data\) + nonencrypted: processing action \(nonencrypted\) + vold: starting service 'vold' + starting_zygote: starting service 'zygote' + starting_zygote_secondary: starting service 'zygote_secondary' + load_persist_props_action: processing action \(load_persist_props_action\) + early-boot: processing action \(early-boot\) + boot: processing action \(boot\) + ueventd: Starting service 'ueventd' + system_mounted: target=/system + data_mounted: target=/data + correction: Updating system time diff=([0-9]+\.?[0-9]*), cuttime=([0-9]+) + servicemanager_start_by_init: starting service 'servicemanager' + zygoteInit: START com.android.internal.os.ZygoteInit + ZygoteMainSystemServer: app_process\smain\swith\sargv.*\-\-start\-system\-server + ZygoteMainOthers: app_process\smain\swith\sargv + zygote_preload_start: Zygote\s*:\s*begin preload + zygote_preload_classes_start: Zygote\s*:\s*Preloading classes... + zygote_preload_res_start: Zygote\s*:\s*Preloading resources... + zygote_preload_end: Zygote\s*:\s*end preload + zygote_create_system_server: Zygote\s*:\s*System server process [0-9]* has been created + SystemServer_start: Entered the Android system server! + system_server_ready: Enabled StrictMode for system server main + PackageManagerInit_start: SystemServer\s*:\s*StartPackageManagerService + BluetoothService_start: Starting com.android.server.BluetoothService + SystemUi_start: for service com.android.systemui/. + CarLauncherReady: Em.Overview:\s*onResume + CarService_start: for service com.android.car/.CarService + BootAnimStart: starting service 'bootanim' + BootAnimSfWait: BootAnimation:\sWaiting\sfor\sSurfaceFlinger\stook\s + BootAnimShowStart: BootAnimation:\sBootAnimationShownTiming\sstart\stime + BootAnimStopRequest: TELLING SURFACE FLINGER WE ARE BOOTED + BootAnimEnd: Service 'bootanim' + KeyguardStart: KeyguardServiceDelegate.*\*\*\* Keyguard started + KeyguardConnected: KeyguardServiceDelegate.*\*\*\* Keyguard connected + KeyguardShown: KeyguardServiceDelegate.*\*\*\*\* SHOWN CALLED \*\*\*\* + BootComplete: Starting phase 1000 + BootComplete_kernel: processing action \(sys\.boot_completed=1\) + LauncherStart: START.*HOME.*(NexusLauncherActivity|GEL|LensPickerTrampolineActivity|SetupWizardActivity) + FsStat: fs_stat, partition:userdata stat:(0x\S+) +shutdown_events: + ShutdownStart: ShutdownThread:\sNotifying thread to start shutdown + ShutdownBroadcast: ShutdownThread:\sSending shutdown broadcast + ShutdownActivityManagerService: ShutdownThread:\sShutting down activity manager + ShutdownPackageManagerService: ShutdownThread:\sShutting down package manager + ShutdownNfc: ShutdownThread:\sTurning off NFC + ShutdownBt: ShutdownThread:\sDisabling Bluetooth + ShutdownRadio: ShutdownThread:\sTurning off cellular radios + ShutdownRadiosWait: ShutdownThread:\sWaiting for NFC, Bluetooth and Radio + ShutdownBtDone: ShutdownThread:\sBluetooth turned off + ShutdownRadioDone: ShutdownThread:\sRadio turned off + ShutdownNfcDone: ShutdownThread:\sNFC turned off + ShutdownRadiosWaitDone: ShutdownThread:\sNFC, Radio and Bluetooth shutdown complete + ShutdownRadiosWaitTimeout: ShutdownThread:\sTimed out waiting for NFC, Radio and Bluetooth shutdown + ShutdownStorageManagerSerivce: ShutdownThread:\sShutting down StorageManagerService + ShutdownStorageManagerSerivceDone: ShutdownThread:\sResult code [\d]+ from StorageManagerService\.shutdown + ShutdownStorageManagerSerivceTimeout: ShutdownThread:\sShutdown wait timed out + ShutdownStartDone: ShutdownThread:\sPerforming low-level shutdown + ShutdownInitAction: init\s+:\sprocessing action \(sys\.shutdown\.requested + ShutdownInitFsShutdown: init\s+:\sShutdown timeout diff --git a/boottime_tools/bootanalyze/stressfs/Android.mk b/boottime_tools/bootanalyze/stressfs/Android.mk new file mode 100644 index 00000000..2e54e64b --- /dev/null +++ b/boottime_tools/bootanalyze/stressfs/Android.mk @@ -0,0 +1,29 @@ +# Copyright (C) 2017 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. +# +# + +LOCAL_PATH := $(call my-dir) + +include $(CLEAR_VARS) + +LOCAL_PACKAGE_NAME := StressFS +LOCAL_SRC_FILES := $(call all-java-files-under, src) + +LOCAL_MODULE_TAGS := tests +LOCAL_SDK_VERSION := current + +LOCAL_PROGUARD_FLAG_FILES := proguard.flags + +include $(BUILD_PACKAGE) diff --git a/boottime_tools/bootanalyze/stressfs/AndroidManifest.xml b/boottime_tools/bootanalyze/stressfs/AndroidManifest.xml new file mode 100644 index 00000000..8713c511 --- /dev/null +++ b/boottime_tools/bootanalyze/stressfs/AndroidManifest.xml @@ -0,0 +1,38 @@ +<?xml version="1.0" encoding="utf-8"?> +<!-- Copyright (C) 2017 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. +--> + +<manifest xmlns:android="http://schemas.android.com/apk/res/android" + package="com.android.car.test.stressfs"> + + <original-package android:name="com.android.car.test.stressfs" /> + + <uses-sdk android:minSdkVersion="25" + android:targetSdkVersion="25" /> + <uses-permission android:name="android.permission.WRITE_EXTERNAL_STORAGE" /> + + <application android:label="Stress Filesystem" + android:directBootAware="true" + android:allowBackup="false"> + + <activity android:name=".WritingActivity"> + <intent-filter> + <action android:name="com.android.car.test.stressfs.START" /> + </intent-filter> + </activity> + <service android:name=".WritingService"> + </service> + </application> +</manifest> diff --git a/boottime_tools/bootanalyze/stressfs/proguard.flags b/boottime_tools/bootanalyze/stressfs/proguard.flags new file mode 100644 index 00000000..1e5ff3dd --- /dev/null +++ b/boottime_tools/bootanalyze/stressfs/proguard.flags @@ -0,0 +1,3 @@ +-verbose +-keep public class * extends android.app.Activity +-keep public class * extends android.app.Service diff --git a/boottime_tools/bootanalyze/stressfs/src/com/android/car/test/stressfs/WritingActivity.java b/boottime_tools/bootanalyze/stressfs/src/com/android/car/test/stressfs/WritingActivity.java new file mode 100644 index 00000000..6fe5cc61 --- /dev/null +++ b/boottime_tools/bootanalyze/stressfs/src/com/android/car/test/stressfs/WritingActivity.java @@ -0,0 +1,61 @@ +/* + * Copyright (C) 2017 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. + */ +package com.android.car.test.stressfs; + +import android.app.Activity; +import android.content.ComponentName; +import android.content.Context; +import android.content.Intent; +import android.content.ServiceConnection; +import android.os.Bundle; +import android.os.IBinder; + +/** + * Used to instantiate the WritingService service at a high priority. + */ +public class WritingActivity extends Activity { + + private static final String TAG = "StressFS"; + + /** + * Activity-wide connection to keep the service going. + * Not used for any specific interaction. + */ + private ServiceConnection mConnection = new ServiceConnection() { + /** No-op */ + public void onServiceConnected(ComponentName className, IBinder service) { + // Nothing to do. + } + + /** No-op */ + public void onServiceDisconnected(ComponentName className) { + // Nothing to do. + } + }; + + @Override + public void onCreate(Bundle savedInstanceState) { + super.onCreate(savedInstanceState); + bindService( + new Intent( + getIntent().getAction(), + getIntent().getData(), + this, + WritingService.class), + mConnection, + Context.BIND_AUTO_CREATE); + } +} diff --git a/boottime_tools/bootanalyze/stressfs/src/com/android/car/test/stressfs/WritingService.java b/boottime_tools/bootanalyze/stressfs/src/com/android/car/test/stressfs/WritingService.java new file mode 100644 index 00000000..0db75d45 --- /dev/null +++ b/boottime_tools/bootanalyze/stressfs/src/com/android/car/test/stressfs/WritingService.java @@ -0,0 +1,186 @@ +/* + * Copyright (C) 2017 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. + */ +package com.android.car.test.stressfs; + +import android.app.Service; +import android.app.Notification; +import android.app.NotificationChannel; +import android.content.Context; +import android.content.Intent; +import android.net.Uri; +import android.os.Binder; +import android.os.Bundle; +import android.os.Environment; +import android.os.IBinder; +import android.util.Log; +import android.R.drawable; + +import java.io.*; +import java.util.*; + +/** + * Used to stress the file writing before and during shutdown to help ensure + * that the filesystem shuts down at the right time, in a consistent manner, + * and does not get corrupted. + * + * Writes to two files - one on the data partition, one on the external storage + * partition - simultaneous in two separate threads; starting over after a + * certain amount of data is written. + * + * This class is intended to be invoked from the shell. For a 64KB file + * written in 1KB chunks, invoke from the host workstation: + * adb install -g StressFS.apk + * adb shell am start \ + * -n com.android.car.test.stressfs/.WritingActivity \ + * -a com.android.car.test.stressfs.START + * -d "stressfs://start?block=1024\&file=65536" + * + * After reboot: + * adb uninstall com.android.car.test.stressfs + * adb shell "rm -rf /storage/emulated/0/stressfs_data*" + * + * On boot after running this while shutting down, fsck should flag any + * corruption that it sees resulting from this running. The goal is to set the + * shutdown sequence in a manner that does not corrupt so that this check can + * be avoided. + */ +public class WritingService extends Service { + + private static final String TAG = "StressFS"; + + private static final String ACTION_START = "com.android.car.test.stressfs.START"; + + private static final int DEFAULT_BLOCK_SIZE = 4096; + private static final int DEFAULT_FILE_SIZE = 16 * 1024 * 1024; + + private static final String FILENAME_PREFIX = "stressfs_data_"; + + private static final int NOTIFICATION_ID = 100; + + /** Continuously writes test data to a specified file. */ + private static class WriteToDisk extends Thread { + private final String mLogTag; + private final File mFile; + private final int mFileSize; + private final byte[] mTestData; + + public WriteToDisk( + String logTag, + File file, + int fileSize, + byte[] testData) { + mLogTag = logTag; + mFile = file; + mFileSize = fileSize; + mTestData = testData; + } + + /** Writes data to a file, restarting once the maximum amount of data is reached.*/ + @Override + public void run() { + Log.d(TAG, mLogTag + " thread started"); + while (true) { + try { + FileOutputStream fos = new FileOutputStream(mFile); + // Write in chunks until the amount of data requested + // is written. + for (int j = 0; j < mFileSize; j += mTestData.length) { + fos.write(mTestData); + } + fos.close(); + } catch (FileNotFoundException e) { + Log.e(TAG, "File not found: ", e); + } catch (IOException e) { + Log.e(TAG, "IO error: ", e); + } + } + } + } + + /** Raises service priority and starts the writing threads. */ + @Override + public IBinder onBind(Intent intent) { + Notification notification = + new Notification.Builder(this, NotificationChannel.DEFAULT_CHANNEL_ID) + .setContentTitle("Stress Filesystem service running.") + .setSmallIcon(drawable.ic_menu_save) + .build(); + + // Raise priority of this service. + startForeground(NOTIFICATION_ID, notification); + + File dataPartitionFile = getFileStreamPath(FILENAME_PREFIX + UUID.randomUUID()); + File externalPartitionFile = new File( + Environment.getExternalStorageDirectory(), FILENAME_PREFIX + UUID.randomUUID()); + + Log.i(TAG, "External storage state: " + + Environment.getExternalStorageState(externalPartitionFile)); + + Uri data = intent.getData(); + if (data != null) { + Log.i(TAG, "Data: " + data.toString()); + } + int blockSize = getQueryParam(data, "block", DEFAULT_BLOCK_SIZE); + int fileSize = getQueryParam(data, "file", DEFAULT_FILE_SIZE); + Log.i(TAG, "Block Size: " + blockSize); + Log.i(TAG, "File Size: " + fileSize); + + if (fileSize % blockSize != 0) { + Log.w(TAG, "File size should be a multiple of block size."); + } + + // Populate some test data. + StringBuilder builder = new StringBuilder(blockSize); + for (int i = 0; i < builder.capacity(); i++) { + builder.append((char)(i % 26 + 'A')); + } + byte[] testData = new String(builder).getBytes(); + + // Spawn two threads - one to write to the /data partition, one to + // write to the SD card. + new WriteToDisk("data", dataPartitionFile, fileSize, testData).start(); + new WriteToDisk("external", externalPartitionFile, fileSize, testData).start(); + + // No need to return a binder interface, since there is no more + // interaction needed from the activity starting the service. + return null; + } + + /** Keeps service alive once started. */ + @Override + public int onStartCommand(Intent intent, int flags, int startId) { + return START_STICKY; + } + + /** Parses an integer query parameter from the input Uri. */ + private int getQueryParam(Uri data, String key, int defaultValue) { + if (data == null) { + return defaultValue; + } + String inValString = data.getQueryParameter(key); + if (inValString != null) { + try { + int inVal = Integer.parseInt(inValString); + if (inVal != 0) { + return inVal; + } + } catch (NumberFormatException e) { + return defaultValue; + } + } + return defaultValue; + } +} diff --git a/boottime_tools/bootio/Android.mk b/boottime_tools/bootio/Android.mk new file mode 100644 index 00000000..e4db8355 --- /dev/null +++ b/boottime_tools/bootio/Android.mk @@ -0,0 +1,76 @@ +# +# 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. +# + +LOCAL_PATH := $(call my-dir) + +bootio_lib_src_files := \ + protos.proto \ + bootio_collector.cpp \ + +bootio_src_files := \ + bootio.cpp \ + +bootio_shared_libs := \ + libbase \ + libcutils \ + liblog \ + libprotobuf-cpp-lite \ + +bootio_cflags := \ + -Wall \ + -Werror \ + -Wextra \ + +define bootio_proto_include +$(call local-generated-sources-dir)/proto/$(LOCAL_PATH) +endef + +# bootio static library +# ----------------------------------------------------------------------------- + +include $(CLEAR_VARS) + +LOCAL_MODULE := libbootio +LOCAL_MODULE_CLASS := SHARED_LIBRARIES + +LOCAL_C_INCLUDES := \ + $(LOCAL_PATH)/.. \ + $(call bootio_proto_include) \ + +LOCAL_EXPORT_C_INCLUDE_DIRS := $(LOCAL_PATH) +LOCAL_CFLAGS := $(bootio_cflags) +LOCAL_SHARED_LIBRARIES := $(bootio_shared_libs) +LOCAL_PROTOC_OPTIMIZE_TYPE := lite +LOCAL_SRC_FILES := $(bootio_lib_src_files) + +include $(BUILD_SHARED_LIBRARY) + + +# bootio binary +# ----------------------------------------------------------------------------- + +include $(CLEAR_VARS) + +LOCAL_MODULE := bootio +LOCAL_CFLAGS := $(bootio_cflags) +LOCAL_SHARED_LIBRARIES := \ + $(bootio_shared_libs) \ + libbootio \ + +LOCAL_INIT_RC := bootio.rc +LOCAL_SRC_FILES := $(bootio_src_files) + +include $(BUILD_EXECUTABLE) diff --git a/boottime_tools/bootio/README.md b/boottime_tools/bootio/README.md new file mode 100644 index 00000000..ca075ded --- /dev/null +++ b/boottime_tools/bootio/README.md @@ -0,0 +1,24 @@ +# bootio # + +The bootio tool records I/O for processes during boot. +To use bootio kernel must be compiled with this flags: + + CONFIG_TASKSTATS=y + CONFIG_TASK_DELAY_ACCT=y + CONFIG_TASK_XACCT=y + CONFIG_TASK_IO_ACCOUNTING=y + +To use bootio make sure it's included in product config for the board. +Create file /data/misc/bootio/start with a command like the following: + + adb shell 'echo "$TIMEOUT $SAMPLES" > /data/misc/bootio/start' + +Where the value of $TIMEOUT corresponds to the desired bootio period in +seconds and $SAMPLES corresponds to the desired number of samples. + +Note: /data/misc/bootio/start is not deleted automatically, so don't +forget to delete it when you're done collecting data. + +To see collected logs run: + + adb shell bootio -p diff --git a/boottime_tools/bootio/bootio.cpp b/boottime_tools/bootio/bootio.cpp new file mode 100644 index 00000000..629d04a7 --- /dev/null +++ b/boottime_tools/bootio/bootio.cpp @@ -0,0 +1,162 @@ +/* + * 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. + */ + +// The bootio tool provides options to collect I/O stats for processes during boot. + +#include <vector> +#include <getopt.h> +#include <unistd.h> +#include <android-base/file.h> +#include <android-base/logging.h> +#include <android-base/strings.h> +#include <log/log.h> + +#include "bootio_collector.h" + +namespace android { + +#define LOG_ROOT "/data/misc/bootio" +#define LOG_START_FILE LOG_ROOT"/start" +#define SELF_IO "/proc/self/io" + +static const int LOG_TIMEOUT_INDEX = 0; +static const int LOG_SAMPLES_INDEX = 1; +static const int LOG_MAX_TIMEOUT = 120; +static const int LOG_MAX_SAMPLES = 30; + +void ShowHelp(const char *cmd) { + fprintf(stderr, "Usage: %s [options]\n", cmd); + fprintf(stderr, + "options include:\n" + " -h, --help Show this help\n" + " -p, --print Dump the boot io data to the console\n" + "\nNo options will start data collection process.\n"); +} + +void PrintBootIo() { + printf("Boot I/O:\n"); + printf("------------\n"); + std::unique_ptr <BootioCollector> collector(new BootioCollector(LOG_ROOT)); + if (collector.get() == NULL) { + LOG(ERROR) << "Failed to create data collector"; + return; + } + collector->Print(); +} + +void StartDataCollection() { + if (access(SELF_IO, F_OK) == -1) { + LOG(ERROR) << "Kernel doesn't support I/O profiling."; + printf("Kernel doesn't support I/O profiling."); + return; + } + + int timeout = 0; + int samples = 0; + + std::string start; + android::base::ReadFileToString(LOG_START_FILE, &start); + + if (!start.empty()) { + std::vector <std::string> components = android::base::Split(start, " "); + if (components.size() != 2) { + LOG(ERROR) << "Invalid value in start file." << start; + return; + } + timeout = atoi(components.at(LOG_TIMEOUT_INDEX).c_str()); + samples = atoi(components.at(LOG_SAMPLES_INDEX).c_str()); + } else { + LOG(INFO) << "No profiling requested. Exiting"; + printf("Boot I/O: no profiling requested. Exiting.\n"); + return; + } + if (timeout <= 0 || samples <= 0) { + LOG(ERROR) << "Boot I/O: failed to parse string:" << start; + printf("Boot I/O: failed to parse string: %s\n", start.c_str()); + return; + } + if (samples > timeout || samples > LOG_MAX_SAMPLES || timeout > LOG_MAX_TIMEOUT) { + LOG(ERROR) << "Bad values for bootio. timeout=" << timeout << + " samples=" << samples << " Max timeout=" << LOG_MAX_TIMEOUT << + " Max samples=" << LOG_MAX_SAMPLES; + return; + } + LOG(INFO) << "Boot I/O: collecting data. samples=" << samples << "timeout=" << timeout; + printf("Boot I/O: collecting data\ntimeout=%d, samples=%d\n", + timeout, samples); + std::unique_ptr <BootioCollector> collector(new BootioCollector(LOG_ROOT)); + if (collector.get() == NULL) { + LOG(ERROR) << "Failed to create data collector"; + return; + } + collector->StartDataCollection(timeout, samples); +} + +} + +int main(int argc, char **argv) { + android::base::InitLogging(argv); + + LOG(INFO) << "Bootio started"; + + int optionIndex = 0; + static const struct option longOptions[] = { + {"help", no_argument, NULL, 'h'}, + {"print", no_argument, NULL, 'p'}, + {NULL, 0, NULL, 0} + }; + + int opt = 0; + bool startCollection = true; + while ((opt = getopt_long(argc, argv, "hlpr:", longOptions, &optionIndex)) != -1) { + switch (opt) { + case 0: { + const std::string option_name = longOptions[optionIndex].name; + LOG(ERROR) << "Invalid option: " << option_name; + break; + } + + case 'h': { + android::ShowHelp(argv[0]); + startCollection = false; + break; + } + + case 'p': { + android::PrintBootIo(); + startCollection = false; + break; + } + + default: { + DCHECK_EQ(opt, '?'); + + // |optopt| is an external variable set by getopt representing + // the value of the invalid option. + LOG(ERROR) << "Invalid option: " << optopt; + android::ShowHelp(argv[0]); + return EXIT_FAILURE; + } + } + } + + if (startCollection) { + android::StartDataCollection(); + } + + return 0; +} + diff --git a/boottime_tools/bootio/bootio.rc b/boottime_tools/bootio/bootio.rc new file mode 100644 index 00000000..f0074cb4 --- /dev/null +++ b/boottime_tools/bootio/bootio.rc @@ -0,0 +1,10 @@ +# This file is the LOCAL_INIT_RC file for the bootio command. + +service bootio /system/bin/bootio + class main + user root + group root + oneshot + +on post-fs-data + mkdir /data/misc/bootio 0755 root shell diff --git a/boottime_tools/bootio/bootio_collector.cpp b/boottime_tools/bootio/bootio_collector.cpp new file mode 100644 index 00000000..495a9aa4 --- /dev/null +++ b/boottime_tools/bootio/bootio_collector.cpp @@ -0,0 +1,381 @@ +/* + * 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. + */ + +#include "bootio_collector.h" +#include <android-base/logging.h> +#include <android-base/file.h> +#include <log/log.h> +#include "protos.pb.h" +#include "time.h" +#include <unordered_map> +#include <inttypes.h> +#include <dirent.h> + +namespace android { + +#define CPU_STAT_FILE "/proc/stat" +#define SAMPLES_FILE "/samples" +#define PID_STAT_FILE "/proc/%d/stat" +#define PID_CMDLINE_FILE "/proc/%d/cmdline" +#define PID_IO_FILE "/proc/%d/io" +#define PROC_DIR "/proc" + +static const int MAX_LINE = 256; + +#define die(...) { LOG(ERROR) << (__VA_ARGS__); exit(EXIT_FAILURE); } + +void PopulateCpu(CpuData& cpu) { + long unsigned utime, ntime, stime, itime; + long unsigned iowtime, irqtime, sirqtime; + FILE *file; + file = fopen(CPU_STAT_FILE, "r"); + if (!file) die("Could not open /proc/stat.\n"); + fscanf(file, "cpu %lu %lu %lu %lu %lu %lu %lu", &utime, &ntime, &stime, + &itime, &iowtime, &irqtime, &sirqtime); + fclose(file); + cpu.set_utime(utime); + cpu.set_ntime(ntime); + cpu.set_stime(stime); + cpu.set_itime(itime); + cpu.set_iowtime(iowtime); + cpu.set_irqtime(irqtime); + cpu.set_sirqtime(sirqtime); +} + +void ClearPreviousResults(std::string path) { + std::string err; + if (!android::base::RemoveFileIfExists(path, &err)) { + LOG(ERROR) << "failed to remove the file " << path << " " << err; + return; + } +} + +int ReadIo(char *filename, AppSample *sample) { + FILE *file; + char line[MAX_LINE]; + unsigned int rchar, wchar, syscr, syscw, readbytes, writebytes; + + file = fopen(filename, "r"); + if (!file) return 1; + while (fgets(line, MAX_LINE, file)) { + sscanf(line, "rchar: %u", &rchar); + sscanf(line, "wchar: %u", &wchar); + sscanf(line, "syscr: %u", &syscr); + sscanf(line, "syscw: %u", &syscw); + sscanf(line, "read_bytes: %u", &readbytes); + sscanf(line, "write_bytes: %u", &writebytes); + } + fclose(file); + sample->set_rchar(rchar); + sample->set_wchar(wchar); + sample->set_syscr(syscr); + sample->set_syscw(syscw); + sample->set_readbytes(readbytes); + sample->set_writebytes(writebytes); + return 0; +} + +int ReadStatForName(char *filename, AppData *app) { + FILE *file; + char buf[MAX_LINE], *open_paren, *close_paren; + + file = fopen(filename, "r"); + if (!file) return 1; + fgets(buf, MAX_LINE, file); + fclose(file); + + /* Split at first '(' and last ')' to get process name. */ + open_paren = strchr(buf, '('); + close_paren = strrchr(buf, ')'); + if (!open_paren || !close_paren) return 1; + + *open_paren = *close_paren = '\0'; + if (!app->has_tname()) { + app->set_tname(open_paren + 1, close_paren - open_paren - 1); + } + return 0; +} + +int ReadStat(char *filename, AppSample *sample) { + FILE *file; + char buf[MAX_LINE], *open_paren, *close_paren; + + file = fopen(filename, "r"); + if (!file) return 1; + fgets(buf, MAX_LINE, file); + fclose(file); + + /* Split at first '(' and last ')' to get process name. */ + open_paren = strchr(buf, '('); + close_paren = strrchr(buf, ')'); + if (!open_paren || !close_paren) return 1; + + uint64_t utime; + uint64_t stime; + uint64_t rss; + + /* Scan rest of string. */ + sscanf(close_paren + 1, + " %*c " "%*d %*d %*d %*d %*d %*d %*d %*d %*d %*d " + "%" PRIu64 /*SCNu64*/ + "%" PRIu64 /*SCNu64*/ "%*d %*d %*d %*d %*d %*d %*d %*d " + "%" PRIu64 /*SCNu64*/ "%*d %*d %*d %*d %*d %*d %*d %*d %*d %*d %*d %*d %*d %*d %*d", + &utime, + &stime, + &rss); + sample->set_utime(utime); + sample->set_stime(stime); + sample->set_rss(rss); + + return 0; +} + +int ReadCmdline(char *filename, AppData *app) { + FILE *file; + char line[MAX_LINE]; + + line[0] = '\0'; + file = fopen(filename, "r"); + if (!file) return 1; + fgets(line, MAX_LINE, file); + fclose(file); + if (strlen(line) > 0) { + app->set_name(line, strlen(line)); + } else { + app->set_name("N/A"); + } + return 0; +}; + +void ReadProcData(std::unordered_map<int, AppData*>& pidDataMap, DataContainer& dataContainer, + time_t currentTimeUtc, time_t currentUptime) { + DIR *procDir; + struct dirent *pidDir; + pid_t pid; + char filename[64]; + procDir = opendir(PROC_DIR); + if (!procDir) die("Could not open /proc.\n"); + while ((pidDir = readdir(procDir))) { + if (!isdigit(pidDir->d_name[0])) { + continue; + } + pid = atoi(pidDir->d_name); + AppData *data; + + // TODO: in theory same pid can be shared for multiple processes, + // might need add extra check. + if (pidDataMap.count(pid) == 0) { + data = dataContainer.add_app(); + data->set_pid(pid); + sprintf(filename, PID_STAT_FILE, pid); + ReadStatForName(filename, data); + sprintf(filename, PID_CMDLINE_FILE, pid); + ReadCmdline(filename, data); + pidDataMap[pid] = data; + } else { + data = pidDataMap[pid]; + } + AppSample *sample = data->add_samples(); + sample->set_timestamp(currentTimeUtc); + sample->set_uptime(currentUptime); + + sprintf(filename, PID_STAT_FILE, pid); + ReadStat(filename, sample); + + sprintf(filename, PID_IO_FILE, pid); + ReadIo(filename, sample); + } +} + +uint64_t SumCpuValues(CpuData& cpu) { + return cpu.utime() + cpu.ntime() + cpu.stime() + cpu.itime() + cpu.iowtime() + + cpu.irqtime() + cpu.sirqtime(); +} + +time_t GetUptime() { + std::string uptime_str; + if (!android::base::ReadFileToString("/proc/uptime", &uptime_str)) { + LOG(ERROR) << "Failed to read /proc/uptime"; + return -1; + } + + // Cast intentionally rounds down. + return static_cast<time_t>(strtod(uptime_str.c_str(), NULL)); +} + +struct Stats { + int uptime; + float cpu; + uint64_t rbytes; + uint64_t wbytes; +}; + +void PrintPids(DataContainer& data, std::unordered_map<int, uint64_t>& cpuDataMap) { + printf("rchar: number of bytes the process read, using any read-like system call " + "(from files, pipes, tty...).\n"); + printf("wchar: number of bytes the process wrote using any write-like system call.\n"); + printf("wchar: number of bytes the process wrote using any write-like system call.\n"); + printf("syscr: number of write-like system call invocations that the process performed.\n"); + printf("rbytes: number of bytes the process directly read from disk.\n"); + printf("wbytes: number of bytes the process originally dirtied in the page-cache " + "(assuming they will go to disk later).\n\n"); + + std::unique_ptr<AppSample> bootZeroSample(new AppSample()); + std::map<int, Stats> statsMap; + // Init stats map + Stats emptyStat {0, 0., 0, 0}; + for (auto it = cpuDataMap.begin(); it != cpuDataMap.end(); it++) { + statsMap[it->first] = emptyStat; + } + for (int i = 0; i < data.app_size(); i++) { + const AppData appData = data.app(i); + printf("\n-----------------------------------------------------------------------------\n"); + printf("PID:\t%u\n", appData.pid()); + printf("Name:\t%s\n", appData.name().c_str()); + printf("ThName:\t%s\n", appData.tname().c_str()); + printf("%-15s%-13s%-13s%-13s%-13s%-13s%-13s%-13s\n", "Uptime inter.", "rchar", "wchar", + "syscr", "syscw", "rbytes", "wbytes", "cpu%"); + const AppSample *olderSample = NULL; + const AppSample *newerSample = NULL; + bool isFirstSample = true; + for (int j = 0; j < appData.samples_size(); j++) { + olderSample = newerSample; + newerSample = &(appData.samples(j)); + if (olderSample == NULL) { + olderSample = bootZeroSample.get(); + } + float cpuLoad = 0.; + uint64_t cpuDelta; + if (isFirstSample) { + cpuDelta = cpuDataMap[newerSample->timestamp()]; + } else { + cpuDelta = cpuDataMap[newerSample->timestamp()] - + cpuDataMap[olderSample->timestamp()]; + } + if (cpuDelta != 0) { + cpuLoad = (newerSample->utime() - olderSample->utime() + + newerSample->stime() - olderSample->stime()) * 100. / cpuDelta; + } + Stats& stats = statsMap[newerSample->timestamp()]; + stats.uptime = newerSample->uptime(); + stats.cpu += cpuLoad; + stats.rbytes += (newerSample->readbytes() - olderSample->readbytes()); + stats.wbytes += (newerSample->writebytes() - olderSample->writebytes()); + + // Note that all of these are explicitly `long long`s, not int64_t, + // so we can't use PRId64 here. +#define NUMBER "%-13lld" + printf("%5lld - %-5lld " NUMBER NUMBER NUMBER NUMBER NUMBER NUMBER "%-9.2f\n", +#undef NUMBER + olderSample->uptime(), + newerSample->uptime(), + newerSample->rchar() - olderSample->rchar(), + newerSample->wchar() - olderSample->wchar(), + newerSample->syscr() - olderSample->syscr(), + newerSample->syscw() - olderSample->syscw(), + newerSample->readbytes() - olderSample->readbytes(), + newerSample->writebytes() - olderSample->writebytes(), + cpuLoad); + isFirstSample = false; + } + printf("-----------------------------------------------------------------------------\n"); +#define NUMBER "%-13lld" + printf("%-15s" NUMBER NUMBER NUMBER NUMBER NUMBER NUMBER "\n", +#undef NUMBER + "Total", + newerSample->rchar(), + newerSample->wchar(), + newerSample->syscr(), + newerSample->syscw(), + newerSample->readbytes(), + newerSample->writebytes()); + } + printf("\nAggregations\n%-10s%-13s%-13s%-13s\n", + "Total", + "rbytes", + "wbytes", + "cpu%"); + + for (auto it = statsMap.begin(); it != statsMap.end(); it++) { + printf("%-10u%-13" PRIu64 "%-13" PRIu64 "%-9.2f\n", + it->second.uptime, + it->second.rbytes, + it->second.wbytes, + it->second.cpu); + } +} + +} + +BootioCollector::BootioCollector(std::string path) { + DCHECK_EQ('/', path.back()); + path_ = path; +} + +void BootioCollector::StartDataCollection(int timeout, int samples) { + android::ClearPreviousResults(getStoragePath()); + int remaining = samples + 1; + int delayS = timeout / samples; + + std::unordered_map < int, AppData * > pidDataMap; + std::unique_ptr <DataContainer> data(new DataContainer()); + while (remaining > 0) { + time_t currentTimeUtc = time(nullptr); + time_t currentUptime = android::GetUptime(); + CpuData *cpu = data->add_cpu(); + cpu->set_timestamp(currentTimeUtc); + cpu->set_uptime(currentUptime); + android::PopulateCpu(*cpu); + android::ReadProcData(pidDataMap, *data.get(), currentTimeUtc, currentUptime); + remaining--; + if (remaining == 0) { + continue; + } + sleep(delayS); + } + std::string file_data; + if (!data->SerializeToString(&file_data)) { + LOG(ERROR) << "Failed to serialize"; + return; + } + if (!android::base::WriteStringToFile(file_data, getStoragePath())) { + LOG(ERROR) << "Failed to write samples"; + } +} + +void BootioCollector::Print() { + std::string file_data; + if (!android::base::ReadFileToString(getStoragePath(), &file_data)) { + printf("Failed to read data from file.\n"); + return; + } + std::unique_ptr <DataContainer> data(new DataContainer()); + if (!data->ParsePartialFromString(file_data)) { + printf("Failed to parse data.\n"); + return; + } + std::unordered_map<int, uint64_t> cpuDataMap; + for (int i = 0; i < data->cpu_size(); i++) { + CpuData cpu_data = data->cpu(i); + cpuDataMap[cpu_data.timestamp()] = android::SumCpuValues(cpu_data); + } + android::PrintPids(*data.get(), cpuDataMap); +} + + +std::string BootioCollector::getStoragePath() { + return path_ + SAMPLES_FILE; +} diff --git a/boottime_tools/bootio/bootio_collector.h b/boottime_tools/bootio/bootio_collector.h new file mode 100644 index 00000000..7296e6f9 --- /dev/null +++ b/boottime_tools/bootio/bootio_collector.h @@ -0,0 +1,39 @@ +/* + * 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. + */ + +#ifndef BOOTIO_COLLECTOR_H_ +#define BOOTIO_COLLECTOR_H_ + +#include <string> +#include <android-base/macros.h> + +class BootioCollector { +public: + BootioCollector(std::string path); + + void StartDataCollection(int timeout, int samples); + + void Print(); + +private: + std::string getStoragePath(); + + std::string path_; + + DISALLOW_COPY_AND_ASSIGN(BootioCollector); +}; + +#endif // BOOTIO_COLLECTOR_H_ diff --git a/boottime_tools/bootio/protos.proto b/boottime_tools/bootio/protos.proto new file mode 100644 index 00000000..d5674ece --- /dev/null +++ b/boottime_tools/bootio/protos.proto @@ -0,0 +1,55 @@ +// 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. + +syntax = "proto2"; + +option optimize_for = LITE_RUNTIME; + +message DataContainer { + repeated AppData app = 1; + repeated CpuData cpu = 2; +}; + +message CpuData { + required int64 timestamp = 1; + required int64 uptime = 2; + required int64 utime = 3; + required int64 ntime = 4; + required int64 stime = 5; + required int64 itime = 6; + required int64 iowtime = 7; + required int64 irqtime = 9; + required int64 sirqtime = 10; +} + +message AppData { + required int32 pid = 1; + required string tname = 2; + required string name = 3; + repeated AppSample samples = 4; +} + +message AppSample { + required int64 timestamp = 1; + required int64 uptime = 2; + required int64 rchar = 3; + required int64 wchar = 4; + required int64 syscr = 5; + required int64 syscw = 6; + required int64 readbytes = 7; + required int64 writebytes = 8; + required int64 utime = 9; + required int64 stime = 10; + required int64 rss = 11; +}; diff --git a/boottime_tools/bootio/sepolicy/bootio.te b/boottime_tools/bootio/sepolicy/bootio.te new file mode 100644 index 00000000..cd0fb80d --- /dev/null +++ b/boottime_tools/bootio/sepolicy/bootio.te @@ -0,0 +1,12 @@ +# bootio command +type bootio, domain, coredomain; +type bootio_exec, exec_type, file_type; + +init_daemon_domain(bootio) + +# Allow persistent storage in /data/misc/bootio. +#allow bootio bootio_data_file:dir rw_dir_perms; +#allow bootio bootio_data_file:file create_file_perms; + +# Read access to pseudo filesystems (for /proc/stats, proc/io/io, etc). +#r_dir_file(bootio, proc) diff --git a/boottime_tools/bootio/sepolicy/domain.te b/boottime_tools/bootio/sepolicy/domain.te new file mode 100644 index 00000000..af42fe7e --- /dev/null +++ b/boottime_tools/bootio/sepolicy/domain.te @@ -0,0 +1,2 @@ +# dontaudit bootio kernel:system module_request; +allow bootio kernel:fd use;
\ No newline at end of file diff --git a/boottime_tools/bootio/sepolicy/file.te b/boottime_tools/bootio/sepolicy/file.te new file mode 100644 index 00000000..0320bc83 --- /dev/null +++ b/boottime_tools/bootio/sepolicy/file.te @@ -0,0 +1,2 @@ +# /data/misc subdirectories +type bootio_data_file, file_type, data_file_type, core_data_file_type; diff --git a/boottime_tools/bootio/sepolicy/file_contexts b/boottime_tools/bootio/sepolicy/file_contexts new file mode 100644 index 00000000..071227c2 --- /dev/null +++ b/boottime_tools/bootio/sepolicy/file_contexts @@ -0,0 +1,5 @@ +# System files +/system/bin/bootio u:object_r:bootio_exec:s0 + +# Misc data +/data/misc/bootio(/.*)? u:object_r:bootio_data_file:s0 |