#!/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()