1 #!/usr/bin/python 2 3 # Copyright (C) 2017 The Android Open Source Project 4 # 5 # Licensed under the Apache License, Version 2.0 (the "License"); 6 # you may not use this file except in compliance with the License. 7 # You may obtain a copy of the License at 8 # 9 # http://www.apache.org/licenses/LICENSE-2.0 10 # 11 # Unless required by applicable law or agreed to in writing, software 12 # distributed under the License is distributed on an "AS IS" BASIS, 13 # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 14 # See the License for the specific language governing permissions and 15 # limitations under the License. 16 # 17 """Tool to analyze boot-up time from bugreport.""" 18 19 import argparse 20 import collections 21 import datetime 22 import math 23 import operator 24 import os 25 import re 26 import select 27 import subprocess 28 import sys 29 import time 30 import threading 31 import yaml 32 33 from datetime import datetime, date 34 35 DBG = True 36 37 LOG_START_PATTERN = r"""\-\-\-\-\-\-\s(.*)\s\-\-\-\-\-\-""" 38 LOG_END_PATTERN = r"""\-\-\-\-\-\-\s\S.*\s\-\-\-\-\-\-""" 39 40 KERNEL_LOG_TITLE = "KERNEL LOG" 41 SYSYEM_LOG_TITLE = "SYSTEM LOG" 42 LAST_KMSG_TITLE = "LAST KMSG" 43 LAST_LOGCAT_TITLE = "LAST LOGCAT" 44 45 SYSTEM_PROPS_TITLE = "SYSTEM PROPERTIES" 46 47 TIME_DMESG = "\[\s*(\d+\.\d+)\]" 48 TIME_LOGCAT = "(\d+)\-(\d+)\s(\d+):(\d+):(\d+\.\d+)" 49 50 NATIVE_CRASH_START_PATTERN = "I\sDEBUG\s+:\s\*\*\*\s\*\*\*" 51 NATIVE_CRASH_PATTERN = "I\sDEBUG\s+:" 52 JAVA_CRASH_START_PATTERN = "E\sAndroidRuntime:\sFATAL\sEXCEPTION" 53 JAVA_CRASH_PATTERN = "E\sAndroidRuntime:\s" 54 55 EPOCH = datetime.utcfromtimestamp(0) 56 57 def init_arguments(): 58 parser = argparse.ArgumentParser(description='Measures boot time from bugreport.') 59 parser.add_argument('-c', '--config', dest='config', 60 default='config.yaml', type=argparse.FileType('r'), 61 help='config file for the tool') 62 parser.add_argument('bugreport_file', nargs=1, help='bugreport txt file', 63 type=argparse.FileType('r')) 64 parser.add_argument('-n', '--iterate', dest='iterate', type=int, default=1, 65 help='number of time to repeat the measurement', ) 66 return parser.parse_args() 67 68 # Event per each reboot, for distinghishing current boot from last boot 69 class Events: 70 def __init__(self): 71 self.events = collections.OrderedDict() #K: keyword, V:time in ms 72 self.timings = collections.OrderedDict() 73 self.shutdown_events = collections.OrderedDict() 74 self.java_crash = collections.OrderedDict() #K:time, V:list of crash infos, each entry per line 75 self.native_crash = collections.OrderedDict() 76 77 def reset_events_time(self, delta): 78 new_events = collections.OrderedDict() 79 for entry in self.events.iteritems(): 80 new_events[entry[0]] = entry[1] - delta 81 self.events = new_events 82 if len(self.native_crash) > 0: 83 new_crash = collections.OrderedDict() 84 for entry in self.native_crash.iteritems(): 85 new_crash[entry[0] - delta] = entry[1] 86 self.native_crash = new_crash 87 if len(self.java_crash) > 0: 88 new_crash = collections.OrderedDict() 89 for entry in self.java_crash.iteritems(): 90 new_crash[entry[0] - delta] = entry[1] 91 self.java_crash = new_crash 92 93 def reset_shutdown_events_time(self): 94 if len(self.shutdown_events) == 0: 95 return 96 time_offset = 0 97 new_events = collections.OrderedDict() 98 for entry in self.shutdown_events.iteritems(): 99 if time_offset == 0: 100 time_offset = entry[1] 101 new_events[entry[0]] = entry[1] - time_offset 102 self.shutdown_events = new_events 103 104 def dump_dict(self, d): 105 for entry in d.iteritems(): 106 print ' {0:30}: {1}'.format(entry[0], entry[1]) 107 108 def dump_crash(self, time, stack): 109 print " Crash time:", time, " stack:" 110 print ' '.join(stack) 111 112 def dump(self): 113 if len(self.events) > 0: 114 print "\n***Events:" 115 self.dump_dict(self.events) 116 if len(self.timings) > 0: 117 print "\n***Timings top 20" 118 timings_sorted = sorted(self.timings.items(), key = lambda item: item[1], reverse=True) 119 nums_to_dump = min(20, len(timings_sorted)) 120 for i in range(nums_to_dump): 121 print ' {0:30}: {1}'.format(timings_sorted[i][0], timings_sorted[i][1]) 122 print "\n***Timings:" 123 self.dump_dict(self.timings) 124 if len(self.shutdown_events) > 0: 125 print "\n***Shutdown Events (time relative to the begining of shutdown) :" 126 self.dump_dict(self.shutdown_events) 127 if len(self.native_crash) > 0: 128 print "\n***Native crash founds:", len(self.native_crash) 129 for entry in self.native_crash.iteritems(): 130 self.dump_crash(entry[0], entry[1]) 131 if len(self.java_crash) > 0: 132 print "\n***Java crash founds:", len(self.java_crash) 133 for entry in self.java_crash.iteritems(): 134 self.dump_crash(entry[0], entry[1]) 135 136 class Parser: 137 def __init__(self, config_file, bugreport_file): 138 self.re_log_start = re.compile(LOG_START_PATTERN) 139 self.re_log_end = re.compile(LOG_END_PATTERN) 140 self.f = bugreport_file 141 cfg = yaml.load(config_file) 142 self.event_patterns = {key: re.compile(pattern) 143 for key, pattern in cfg['events'].iteritems()} 144 self.timing_patterns = {key: re.compile(pattern) 145 for key, pattern in cfg['timings'].iteritems()} 146 self.shutdown_event_patterns = {key: re.compile(pattern) 147 for key, pattern in cfg['shutdown_events'].iteritems()} 148 self.current_boot_kernel = Events() 149 self.current_boot_logcat = Events() 150 self.last_boot_kernel = Events() 151 self.last_boot_logcat = Events() 152 self.boottime_props = collections.OrderedDict() # K:prop, V:boot time, added in boot time order 153 self.bootloader_time = 0 154 self.re_time_dmesg = re.compile(TIME_DMESG) 155 self.re_time_logcat = re.compile(TIME_LOGCAT) 156 self.re_native_crash_start = re.compile(NATIVE_CRASH_START_PATTERN) 157 self.re_native_crash = re.compile(NATIVE_CRASH_PATTERN) 158 self.re_java_crash_start = re.compile(JAVA_CRASH_START_PATTERN) 159 self.re_java_crash = re.compile(JAVA_CRASH_PATTERN) 160 161 def match_an_event(self, event_patterns, line): 162 for event_key, event_pattern in event_patterns.iteritems(): 163 m = event_pattern.search(line) 164 if m: 165 return event_key, m 166 return None, None 167 168 def get_event_time(self, line, is_kernel): 169 if is_kernel: 170 m = self.re_time_dmesg.search(line) 171 if not m: 172 print "Cannot get time from log:", line 173 return -1 174 return int(float(m.group(1)) * 1000) 175 else: 176 m = self.re_time_logcat.search(line) 177 if not m: 178 print "Cannot get time from log:", line 179 return -1 180 mm = int(m.group(1)) 181 dd = int(m.group(2)) 182 hh = int(m.group(3)) 183 min = int(m.group(4)) 184 usecs = int(float(m.group(5)) * 1000000) 185 secs = usecs / 1000000 186 usecs = usecs - 1000000 * secs 187 dt = datetime(2017, mm, dd, hh, min, secs, usecs) 188 return int((dt - EPOCH).total_seconds() * 1000) 189 190 def queue_crash(self, event, crash_time, crash_stacks, is_native_crash): 191 stacks = list(crash_stacks) 192 if is_native_crash: 193 event.native_crash[crash_time] = stacks 194 else: 195 event.java_crash[crash_time] = stacks 196 197 def check_crash(self, event, orig_line): 198 line = orig_line 199 crash_time = 0 200 crash_stacks = [] 201 is_native_crash = True 202 while len(line) > 0: 203 m = self.re_native_crash_start.search(line) 204 if m: 205 if len(crash_stacks) > 0: 206 self.queue_crash(event, crash_time, crash_stacks, is_native_crash) 207 crash_stacks = [] 208 is_native_crash = True 209 crash_stacks.append(line) 210 crash_time = self.get_event_time(line, False) 211 line = self.f.readline() 212 continue 213 m = self.re_native_crash.search(line) 214 if m: 215 crash_stacks.append(line) 216 line = self.f.readline() 217 continue 218 m = self.re_java_crash_start.search(line) 219 if m: 220 if len(crash_stacks) > 0: 221 self.queue_crash(event, crash_time, crash_stacks, is_native_crash) 222 crash_stacks = [] 223 is_native_crash = False 224 crash_stacks.append(line) 225 crash_time = self.get_event_time(line, False) 226 line = self.f.readline() 227 continue 228 m = self.re_java_crash.search(line) 229 if m: 230 crash_stacks.append(line) 231 line = self.f.readline() 232 continue 233 # reaching here means not crash, so return new line 234 if line != orig_line: 235 return line 236 else: 237 return self.f.readline() 238 239 240 241 def handle_events(self, event, is_kernel): 242 line = self.f.readline() 243 while len(line) > 0 and not self.re_log_end.match(line): 244 key, m = self.match_an_event(self.event_patterns, line) 245 if m: 246 event.events[key] = self.get_event_time(line, is_kernel) 247 line = self.f.readline() 248 continue 249 key, m = self.match_an_event(self.timing_patterns, line) 250 if m: 251 name = m.group('name') 252 time = float(m.group('time')) 253 if key.endswith('_secs'): 254 time = time * 1000 255 event.timings[name] = int(time) 256 line = self.f.readline() 257 continue 258 key, m = self.match_an_event(self.shutdown_event_patterns, line) 259 if m: 260 event.shutdown_events[key] = self.get_event_time(line, is_kernel) 261 line = self.f.readline() 262 continue 263 if not is_kernel: # collect crash 264 line = self.check_crash(event, line) 265 continue 266 line = self.f.readline() 267 268 def handle_kernel_log(self): 269 if DBG: 270 print "start " + KERNEL_LOG_TITLE 271 self.handle_events(self.current_boot_kernel, True) 272 273 def handle_system_log(self): 274 if DBG: 275 print "start " + SYSYEM_LOG_TITLE 276 self.handle_events(self.current_boot_logcat, False) 277 278 def handle_last_kernel_log(self): 279 if DBG: 280 print "start " + LAST_KMSG_TITLE 281 self.handle_events(self.last_boot_kernel, True) 282 283 def handle_last_system_log(self): 284 if DBG: 285 print "start " + LAST_LOGCAT_TITLE 286 self.handle_events(self.last_boot_logcat, False) 287 288 def handle_system_props(self): 289 if DBG: 290 print "start " + SYSTEM_PROPS_TITLE 291 re_prop = re.compile(r"""\[(.+)\].*\[(.*)\]""") 292 RO_BOOTTIME_PROP = "ro.boottime." 293 boottime_props = {} # K: prop name, V: boot time in ms 294 line = self.f.readline() 295 while len(line) > 0 and not self.re_log_end.match(line): 296 m = re_prop.match(line) 297 if not m: 298 print "Cannot parse prop:", line 299 line = self.f.readline() 300 continue 301 if m.group(1).startswith(RO_BOOTTIME_PROP): 302 name = m.group(1)[len(RO_BOOTTIME_PROP):] 303 time = int(m.group(2)) / 1000000 # ns to ms 304 boottime_props[name] = time 305 elif m.group(1) == "ro.boot.boottime": 306 print "Found bootloader boottime ", line 307 entries = m.group(2).split(",") 308 for entry in entries: 309 values = entry.split(":") 310 if values[0] != "SW": 311 self.bootloader_time += int(values[1]) 312 line = self.f.readline() 313 self.boottime_props = collections.OrderedDict(sorted( 314 boottime_props.items(), key = lambda item: item[1])) 315 316 def parse(self): 317 while (True): 318 l = self.f.readline() 319 if len(l) == 0: # EOF 320 return 321 m = self.re_log_start.match(l) 322 if not m: 323 continue 324 #print m.group(1) 325 if m.group(1).startswith(KERNEL_LOG_TITLE): 326 self.handle_kernel_log() 327 elif m.group(1).startswith(SYSYEM_LOG_TITLE): 328 self.handle_system_log() 329 elif m.group(1).startswith(SYSTEM_PROPS_TITLE): 330 self.handle_system_props() 331 elif m.group(1).startswith(LAST_KMSG_TITLE): 332 self.handle_last_kernel_log() 333 elif m.group(1).startswith(LAST_LOGCAT_TITLE): 334 self.handle_last_system_log() 335 336 def dump_props(self): 337 if self.bootloader_time != 0: 338 print "*bootloader time:", self.bootloader_time 339 if self.boottime_props: 340 print "*ro.boottime.*:" 341 for name, t in self.boottime_props.iteritems(): 342 print ' {0:30}: {1}'.format(name, t) 343 344 def reset_event_times(self, kernel_event, logcat_event): 345 has_boot_complete = True 346 kernel_bootcomplete_time = kernel_event.events.get("BootComplete_kernel") 347 if not kernel_bootcomplete_time: 348 has_boot_complete = False 349 logcat_bootcomplete_time = logcat_event.events.get("BootComplete") 350 if not logcat_bootcomplete_time: 351 has_boot_complete = False 352 time_delta = 0 353 if has_boot_complete: 354 time_delta = logcat_bootcomplete_time - kernel_bootcomplete_time 355 else: 356 time_delta = logcat_event.events.values()[0] if len(logcat_event.events) > 0 else 0 357 logcat_event.reset_events_time(time_delta) 358 logcat_event.reset_shutdown_events_time() 359 kernel_event.reset_shutdown_events_time() 360 return has_boot_complete 361 362 def dump(self): 363 self.dump_props() 364 boot_complete_found = self.reset_event_times(self.current_boot_kernel, self.current_boot_logcat) 365 print "* Kernel dmesg:" 366 self.current_boot_kernel.dump() 367 print "\n\n* Logcat " + ("(time matched with kernel dmesg):" if boot_complete_found\ 368 else "(time set relative to the first event):") 369 self.current_boot_logcat.dump() 370 print "\n\n\n==== Data from last boot ===" 371 boot_complete_found = self.reset_event_times(self.last_boot_kernel, self.last_boot_logcat) 372 print "\n\n* Last Kernel dmesg:" 373 self.last_boot_kernel.dump() 374 print "\n\n* Last Logcat " + ("(time matched with kernel dmesg):" if boot_complete_found \ 375 else "(time set relative to the first event):") 376 self.last_boot_logcat.dump() 377 378 def main(): 379 args = init_arguments() 380 381 parser = Parser(args.config, args.bugreport_file[0]) 382 parser.parse() 383 parser.dump() 384 385 if __name__ == '__main__': 386 main() 387
