--- /dev/null
+# 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))
--- /dev/null
+# 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.
--- /dev/null
+#!/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()
--- /dev/null
+#!/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()
--- /dev/null
+#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
--- /dev/null
+# 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)
--- /dev/null
+<?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>
--- /dev/null
+-verbose
+-keep public class * extends android.app.Activity
+-keep public class * extends android.app.Service
--- /dev/null
+/*
+ * 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);
+ }
+}
--- /dev/null
+/*
+ * 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;
+ }
+}
--- /dev/null
+#
+# 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)
--- /dev/null
+# 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
--- /dev/null
+/*
+ * 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;
+}
+
--- /dev/null
+# 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
--- /dev/null
+/*
+ * 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;
+}
--- /dev/null
+/*
+ * 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_
--- /dev/null
+// 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;
+};
--- /dev/null
+# 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)
--- /dev/null
+# dontaudit bootio kernel:system module_request;
+allow bootio kernel:fd use;
\ No newline at end of file
--- /dev/null
+# /data/misc subdirectories
+type bootio_data_file, file_type, data_file_type, core_data_file_type;
--- /dev/null
+# System files
+/system/bin/bootio u:object_r:bootio_exec:s0
+
+# Misc data
+/data/misc/bootio(/.*)? u:object_r:bootio_data_file:s0
OSDN Git Service
