387 lines
14 KiB
Python
387 lines
14 KiB
Python
|
#!/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, Loader=yaml.FullLoader)
|
||
|
|
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()
|