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
19import argparse
20import collections
21import datetime
22import math
23import operator
24import os
25import re
26import select
27import subprocess
28import sys
29import time
30import threading
31import yaml
32
33from datetime import datetime, date
34
35DBG = True
36
37LOG_START_PATTERN = r"""\-\-\-\-\-\-\s(.*)\s\-\-\-\-\-\-"""
38LOG_END_PATTERN = r"""\-\-\-\-\-\-\s\S.*\s\-\-\-\-\-\-"""
39
40KERNEL_LOG_TITLE = "KERNEL LOG"
41SYSYEM_LOG_TITLE = "SYSTEM LOG"
42LAST_KMSG_TITLE = "LAST KMSG"
43LAST_LOGCAT_TITLE = "LAST LOGCAT"
44
45SYSTEM_PROPS_TITLE = "SYSTEM PROPERTIES"
46
47TIME_DMESG = "\[\s*(\d+\.\d+)\]"
48TIME_LOGCAT = "(\d+)\-(\d+)\s(\d+):(\d+):(\d+\.\d+)"
49
50NATIVE_CRASH_START_PATTERN = "I\sDEBUG\s+:\s\*\*\*\s\*\*\*"
51NATIVE_CRASH_PATTERN = "I\sDEBUG\s+:"
52JAVA_CRASH_START_PATTERN = "E\sAndroidRuntime:\sFATAL\sEXCEPTION"
53JAVA_CRASH_PATTERN = "E\sAndroidRuntime:\s"
54
55EPOCH = datetime.utcfromtimestamp(0)
56
57def 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
69class 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
136class 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
378def main():
379  args = init_arguments()
380
381  parser = Parser(args.config, args.bugreport_file[0])
382  parser.parse()
383  parser.dump()
384
385if __name__ == '__main__':
386  main()
387