add bugreport_analyze
- extract boot timing information similar to bootanalyze.py from
unzipped bugreport txt.
- Can be useful for initial investigtion of boot-up issue.
- Print all java / native crashes so that crash during boot-up can
be easily identified.
- also update config.yaml: StartPackageManagerService time was located
in two places and were not counted as timing event.
bug: 64143231
Test: python packages/services/Car/tools/bootanalyze/bugreport_anayze.py -c packages/services/Car/tools/bootanalyze/config.yaml bugreport.tx
Change-Id: I2244074e9f2cdea01e632570c25909f6cd199a43
diff --git a/tools/bootanalyze/bugreport_anayze.py b/tools/bootanalyze/bugreport_anayze.py
new file mode 100644
index 0000000..2575ebf
--- /dev/null
+++ b/tools/bootanalyze/bugreport_anayze.py
@@ -0,0 +1,386 @@
+#!/usr/bin/python
+
+# Copyright (C) 2017 The Android Open Source Project
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+# http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+#
+"""Tool to analyze boot-up time from bugreport."""
+
+import argparse
+import collections
+import datetime
+import math
+import operator
+import os
+import re
+import select
+import subprocess
+import sys
+import time
+import threading
+import yaml
+
+from datetime import datetime, date
+
+DBG = True
+
+LOG_START_PATTERN = r"""\-\-\-\-\-\-\s(.*)\s\-\-\-\-\-\-"""
+LOG_END_PATTERN = r"""\-\-\-\-\-\-\s\S.*\s\-\-\-\-\-\-"""
+
+KERNEL_LOG_TITLE = "KERNEL LOG"
+SYSYEM_LOG_TITLE = "SYSTEM LOG"
+LAST_KMSG_TITLE = "LAST KMSG"
+LAST_LOGCAT_TITLE = "LAST LOGCAT"
+
+SYSTEM_PROPS_TITLE = "SYSTEM PROPERTIES"
+
+TIME_DMESG = "\[\s*(\d+\.\d+)\]"
+TIME_LOGCAT = "(\d+)\-(\d+)\s(\d+):(\d+):(\d+\.\d+)"
+
+NATIVE_CRASH_START_PATTERN = "I\sDEBUG\s+:\s\*\*\*\s\*\*\*"
+NATIVE_CRASH_PATTERN = "I\sDEBUG\s+:"
+JAVA_CRASH_START_PATTERN = "E\sAndroidRuntime:\sFATAL\sEXCEPTION"
+JAVA_CRASH_PATTERN = "E\sAndroidRuntime:\s"
+
+EPOCH = datetime.utcfromtimestamp(0)
+
+def init_arguments():
+ parser = argparse.ArgumentParser(description='Measures boot time from bugreport.')
+ parser.add_argument('-c', '--config', dest='config',
+ default='config.yaml', type=argparse.FileType('r'),
+ help='config file for the tool')
+ parser.add_argument('bugreport_file', nargs=1, help='bugreport txt file',
+ type=argparse.FileType('r'))
+ parser.add_argument('-n', '--iterate', dest='iterate', type=int, default=1,
+ help='number of time to repeat the measurement', )
+ return parser.parse_args()
+
+# Event per each reboot, for distinghishing current boot from last boot
+class Events:
+ def __init__(self):
+ self.events = collections.OrderedDict() #K: keyword, V:time in ms
+ self.timings = collections.OrderedDict()
+ self.shutdown_events = collections.OrderedDict()
+ self.java_crash = collections.OrderedDict() #K:time, V:list of crash infos, each entry per line
+ self.native_crash = collections.OrderedDict()
+
+ def reset_events_time(self, delta):
+ new_events = collections.OrderedDict()
+ for entry in self.events.iteritems():
+ new_events[entry[0]] = entry[1] - delta
+ self.events = new_events
+ if len(self.native_crash) > 0:
+ new_crash = collections.OrderedDict()
+ for entry in self.native_crash.iteritems():
+ new_crash[entry[0] - delta] = entry[1]
+ self.native_crash = new_crash
+ if len(self.java_crash) > 0:
+ new_crash = collections.OrderedDict()
+ for entry in self.java_crash.iteritems():
+ new_crash[entry[0] - delta] = entry[1]
+ self.java_crash = new_crash
+
+ def reset_shutdown_events_time(self):
+ if len(self.shutdown_events) == 0:
+ return
+ time_offset = 0
+ new_events = collections.OrderedDict()
+ for entry in self.shutdown_events.iteritems():
+ if time_offset == 0:
+ time_offset = entry[1]
+ new_events[entry[0]] = entry[1] - time_offset
+ self.shutdown_events = new_events
+
+ def dump_dict(self, d):
+ for entry in d.iteritems():
+ print ' {0:30}: {1}'.format(entry[0], entry[1])
+
+ def dump_crash(self, time, stack):
+ print " Crash time:", time, " stack:"
+ print ' '.join(stack)
+
+ def dump(self):
+ if len(self.events) > 0:
+ print "\n***Events:"
+ self.dump_dict(self.events)
+ if len(self.timings) > 0:
+ print "\n***Timings top 20"
+ timings_sorted = sorted(self.timings.items(), key = lambda item: item[1], reverse=True)
+ nums_to_dump = min(20, len(timings_sorted))
+ for i in range(nums_to_dump):
+ print ' {0:30}: {1}'.format(timings_sorted[i][0], timings_sorted[i][1])
+ print "\n***Timings:"
+ self.dump_dict(self.timings)
+ if len(self.shutdown_events) > 0:
+ print "\n***Shutdown Events (time relative to the begining of shutdown) :"
+ self.dump_dict(self.shutdown_events)
+ if len(self.native_crash) > 0:
+ print "\n***Native crash founds:", len(self.native_crash)
+ for entry in self.native_crash.iteritems():
+ self.dump_crash(entry[0], entry[1])
+ if len(self.java_crash) > 0:
+ print "\n***Java crash founds:", len(self.java_crash)
+ for entry in self.java_crash.iteritems():
+ self.dump_crash(entry[0], entry[1])
+
+class Parser:
+ def __init__(self, config_file, bugreport_file):
+ self.re_log_start = re.compile(LOG_START_PATTERN)
+ self.re_log_end = re.compile(LOG_END_PATTERN)
+ self.f = bugreport_file
+ cfg = yaml.load(config_file)
+ self.event_patterns = {key: re.compile(pattern)
+ for key, pattern in cfg['events'].iteritems()}
+ self.timing_patterns = {key: re.compile(pattern)
+ for key, pattern in cfg['timings'].iteritems()}
+ self.shutdown_event_patterns = {key: re.compile(pattern)
+ for key, pattern in cfg['shutdown_events'].iteritems()}
+ self.current_boot_kernel = Events()
+ self.current_boot_logcat = Events()
+ self.last_boot_kernel = Events()
+ self.last_boot_logcat = Events()
+ self.boottime_props = collections.OrderedDict() # K:prop, V:boot time, added in boot time order
+ self.bootloader_time = 0
+ self.re_time_dmesg = re.compile(TIME_DMESG)
+ self.re_time_logcat = re.compile(TIME_LOGCAT)
+ self.re_native_crash_start = re.compile(NATIVE_CRASH_START_PATTERN)
+ self.re_native_crash = re.compile(NATIVE_CRASH_PATTERN)
+ self.re_java_crash_start = re.compile(JAVA_CRASH_START_PATTERN)
+ self.re_java_crash = re.compile(JAVA_CRASH_PATTERN)
+
+ def match_an_event(self, event_patterns, line):
+ for event_key, event_pattern in event_patterns.iteritems():
+ m = event_pattern.search(line)
+ if m:
+ return event_key, m
+ return None, None
+
+ def get_event_time(self, line, is_kernel):
+ if is_kernel:
+ m = self.re_time_dmesg.search(line)
+ if not m:
+ print "Cannot get time from log:", line
+ return -1
+ return int(float(m.group(1)) * 1000)
+ else:
+ m = self.re_time_logcat.search(line)
+ if not m:
+ print "Cannot get time from log:", line
+ return -1
+ mm = int(m.group(1))
+ dd = int(m.group(2))
+ hh = int(m.group(3))
+ min = int(m.group(4))
+ usecs = int(float(m.group(5)) * 1000000)
+ secs = usecs / 1000000
+ usecs = usecs - 1000000 * secs
+ dt = datetime(2017, mm, dd, hh, min, secs, usecs)
+ return int((dt - EPOCH).total_seconds() * 1000)
+
+ def queue_crash(self, event, crash_time, crash_stacks, is_native_crash):
+ stacks = list(crash_stacks)
+ if is_native_crash:
+ event.native_crash[crash_time] = stacks
+ else:
+ event.java_crash[crash_time] = stacks
+
+ def check_crash(self, event, orig_line):
+ line = orig_line
+ crash_time = 0
+ crash_stacks = []
+ is_native_crash = True
+ while len(line) > 0:
+ m = self.re_native_crash_start.search(line)
+ if m:
+ if len(crash_stacks) > 0:
+ self.queue_crash(event, crash_time, crash_stacks, is_native_crash)
+ crash_stacks = []
+ is_native_crash = True
+ crash_stacks.append(line)
+ crash_time = self.get_event_time(line, False)
+ line = self.f.readline()
+ continue
+ m = self.re_native_crash.search(line)
+ if m:
+ crash_stacks.append(line)
+ line = self.f.readline()
+ continue
+ m = self.re_java_crash_start.search(line)
+ if m:
+ if len(crash_stacks) > 0:
+ self.queue_crash(event, crash_time, crash_stacks, is_native_crash)
+ crash_stacks = []
+ is_native_crash = False
+ crash_stacks.append(line)
+ crash_time = self.get_event_time(line, False)
+ line = self.f.readline()
+ continue
+ m = self.re_java_crash.search(line)
+ if m:
+ crash_stacks.append(line)
+ line = self.f.readline()
+ continue
+ # reaching here means not crash, so return new line
+ if line != orig_line:
+ return line
+ else:
+ return self.f.readline()
+
+
+
+ def handle_events(self, event, is_kernel):
+ line = self.f.readline()
+ while len(line) > 0 and not self.re_log_end.match(line):
+ key, m = self.match_an_event(self.event_patterns, line)
+ if m:
+ event.events[key] = self.get_event_time(line, is_kernel)
+ line = self.f.readline()
+ continue
+ key, m = self.match_an_event(self.timing_patterns, line)
+ if m:
+ name = m.group('name')
+ time = float(m.group('time'))
+ if key.endswith('_secs'):
+ time = time * 1000
+ event.timings[name] = int(time)
+ line = self.f.readline()
+ continue
+ key, m = self.match_an_event(self.shutdown_event_patterns, line)
+ if m:
+ event.shutdown_events[key] = self.get_event_time(line, is_kernel)
+ line = self.f.readline()
+ continue
+ if not is_kernel: # collect crash
+ line = self.check_crash(event, line)
+ continue
+ line = self.f.readline()
+
+ def handle_kernel_log(self):
+ if DBG:
+ print "start " + KERNEL_LOG_TITLE
+ self.handle_events(self.current_boot_kernel, True)
+
+ def handle_system_log(self):
+ if DBG:
+ print "start " + SYSYEM_LOG_TITLE
+ self.handle_events(self.current_boot_logcat, False)
+
+ def handle_last_kernel_log(self):
+ if DBG:
+ print "start " + LAST_KMSG_TITLE
+ self.handle_events(self.last_boot_kernel, True)
+
+ def handle_last_system_log(self):
+ if DBG:
+ print "start " + LAST_LOGCAT_TITLE
+ self.handle_events(self.last_boot_logcat, False)
+
+ def handle_system_props(self):
+ if DBG:
+ print "start " + SYSTEM_PROPS_TITLE
+ re_prop = re.compile(r"""\[(.+)\].*\[(.*)\]""")
+ RO_BOOTTIME_PROP = "ro.boottime."
+ boottime_props = {} # K: prop name, V: boot time in ms
+ line = self.f.readline()
+ while len(line) > 0 and not self.re_log_end.match(line):
+ m = re_prop.match(line)
+ if not m:
+ print "Cannot parse prop:", line
+ line = self.f.readline()
+ continue
+ if m.group(1).startswith(RO_BOOTTIME_PROP):
+ name = m.group(1)[len(RO_BOOTTIME_PROP):]
+ time = int(m.group(2)) / 1000000 # ns to ms
+ boottime_props[name] = time
+ elif m.group(1) == "ro.boot.boottime":
+ print "Found bootloader boottime ", line
+ entries = m.group(2).split(",")
+ for entry in entries:
+ values = entry.split(":")
+ if values[0] != "SW":
+ self.bootloader_time += int(values[1])
+ line = self.f.readline()
+ self.boottime_props = collections.OrderedDict(sorted(
+ boottime_props.items(), key = lambda item: item[1]))
+
+ def parse(self):
+ while (True):
+ l = self.f.readline()
+ if len(l) == 0: # EOF
+ return
+ m = self.re_log_start.match(l)
+ if not m:
+ continue
+ #print m.group(1)
+ if m.group(1).startswith(KERNEL_LOG_TITLE):
+ self.handle_kernel_log()
+ elif m.group(1).startswith(SYSYEM_LOG_TITLE):
+ self.handle_system_log()
+ elif m.group(1).startswith(SYSTEM_PROPS_TITLE):
+ self.handle_system_props()
+ elif m.group(1).startswith(LAST_KMSG_TITLE):
+ self.handle_last_kernel_log()
+ elif m.group(1).startswith(LAST_LOGCAT_TITLE):
+ self.handle_last_system_log()
+
+ def dump_props(self):
+ if self.bootloader_time != 0:
+ print "*bootloader time:", self.bootloader_time
+ if self.boottime_props:
+ print "*ro.boottime.*:"
+ for name, t in self.boottime_props.iteritems():
+ print ' {0:30}: {1}'.format(name, t)
+
+ def reset_event_times(self, kernel_event, logcat_event):
+ has_boot_complete = True
+ kernel_bootcomplete_time = kernel_event.events.get("BootComplete_kernel")
+ if not kernel_bootcomplete_time:
+ has_boot_complete = False
+ logcat_bootcomplete_time = logcat_event.events.get("BootComplete")
+ if not logcat_bootcomplete_time:
+ has_boot_complete = False
+ time_delta = 0
+ if has_boot_complete:
+ time_delta = logcat_bootcomplete_time - kernel_bootcomplete_time
+ else:
+ time_delta = logcat_event.events.values()[0] if len(logcat_event.events) > 0 else 0
+ logcat_event.reset_events_time(time_delta)
+ logcat_event.reset_shutdown_events_time()
+ kernel_event.reset_shutdown_events_time()
+ return has_boot_complete
+
+ def dump(self):
+ self.dump_props()
+ boot_complete_found = self.reset_event_times(self.current_boot_kernel, self.current_boot_logcat)
+ print "* Kernel dmesg:"
+ self.current_boot_kernel.dump()
+ print "\n\n* Logcat " + ("(time matched with kernel dmesg):" if boot_complete_found\
+ else "(time set relative to the first event):")
+ self.current_boot_logcat.dump()
+ print "\n\n\n==== Data from last boot ==="
+ boot_complete_found = self.reset_event_times(self.last_boot_kernel, self.last_boot_logcat)
+ print "\n\n* Last Kernel dmesg:"
+ self.last_boot_kernel.dump()
+ print "\n\n* Last Logcat " + ("(time matched with kernel dmesg):" if boot_complete_found \
+ else "(time set relative to the first event):")
+ self.last_boot_logcat.dump()
+
+def main():
+ args = init_arguments()
+
+ parser = Parser(args.config, args.bugreport_file[0])
+ parser.parse()
+ parser.dump()
+
+if __name__ == '__main__':
+ main()
diff --git a/tools/bootanalyze/config.yaml b/tools/bootanalyze/config.yaml
index 90f68b7..37f2891 100644
--- a/tools/bootanalyze/config.yaml
+++ b/tools/bootanalyze/config.yaml
@@ -1,13 +1,13 @@
#YAML
time_correction_key: correction
timings:
- system_server: SystemServerTiming(Async)?\s*:\s*(?P<name>[^\s]+) took to complete:\s(?P<time>[0-9]+)ms
+ 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
+ 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
@@ -40,7 +40,6 @@
SystemServer_start: Entered the Android system server!
system_server_ready: Enabled StrictMode for system server main
PackageManagerInit_start: SystemServer\s*:\s*StartPackageManagerService
- PackageManagerInit_ready: StartPackageManagerService took to complete
BluetoothService_start: Starting com.android.server.BluetoothService
SystemUi_start: for service com.android.systemui/.
CarLauncherReady: Em.Overview:\s*onResume