blob: 4dc01008e1f557c4f38bc2d37e2f0348841e66c6 [file] [log] [blame]
Vitalii Tomkived4c98c2016-04-28 15:20:57 -07001#!/usr/bin/python
2
3# Copyright (C) 2016 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 logcat and dmesg logs.
18
19bootanalyze read logcat and dmesg loga and determines key points for boot.
20"""
21
Vitalii Tomkivd704edd2016-07-13 17:27:03 -070022import yaml
23import argparse
Vitalii Tomkived4c98c2016-04-28 15:20:57 -070024import re
25import os
Vitalii Tomkivd704edd2016-07-13 17:27:03 -070026import subprocess
Vitalii Tomkived4c98c2016-04-28 15:20:57 -070027import time
Vitalii Tomkivabc92332016-09-20 11:55:44 -070028import math
Vitalii Tomkived4c98c2016-04-28 15:20:57 -070029import datetime
30import sys
31import operator
32
Vitalii Tomkived4c98c2016-04-28 15:20:57 -070033TIME_DMESG = "\[\s*(\d+\.\d+)\]"
Vitalii Tomkiv49dcaf22016-10-31 11:25:01 -070034TIME_LOGCAT = "[0-9]+\.?[0-9]*"
Vitalii Tomkivabc92332016-09-20 11:55:44 -070035VALUE_TOO_BIG = 600
36MAX_RETRIES = 5
Vitalii Tomkiv49dcaf22016-10-31 11:25:01 -070037DEBUG = False
Vitalii Tomkived4c98c2016-04-28 15:20:57 -070038
Vitalii Tomkived4c98c2016-04-28 15:20:57 -070039def main():
Vitalii Tomkivd704edd2016-07-13 17:27:03 -070040 args = init_arguments()
Vitalii Tomkived4c98c2016-04-28 15:20:57 -070041
Vitalii Tomkivabc92332016-09-20 11:55:44 -070042 if args.iterate < 1:
43 raise Exception('Number of iteration must be >=1');
44
45 if args.iterate > 1 and not args.reboot:
46 print "Forcing reboot flag"
47 args.reboot = True
Vitalii Tomkived4c98c2016-04-28 15:20:57 -070048
Vitalii Tomkivd704edd2016-07-13 17:27:03 -070049 cfg = yaml.load(args.config)
Vitalii Tomkived4c98c2016-04-28 15:20:57 -070050
Vitalii Tomkivd704edd2016-07-13 17:27:03 -070051 search_events = {key: re.compile(pattern)
52 for key, pattern in cfg['events'].iteritems()}
Vitalii Tomkiv49dcaf22016-10-31 11:25:01 -070053 timing_events = {key: re.compile(pattern)
54 for key, pattern in cfg['timings'].iteritems()}
Vitalii Tomkivd704edd2016-07-13 17:27:03 -070055 if 'stop_event' not in cfg:
56 raise Exception('Logcat stop_event is missing in config');
Vitalii Tomkived4c98c2016-04-28 15:20:57 -070057
Vitalii Tomkivabc92332016-09-20 11:55:44 -070058 data_points = {}
Vitalii Tomkiv49dcaf22016-10-31 11:25:01 -070059 timing_points = {}
Vitalii Tomkivabc92332016-09-20 11:55:44 -070060 for it in range(0, args.iterate):
61 if args.iterate > 1:
62 print "Run: {0}".format(it + 1)
63 attempt = 1
64 processing_data = None
Vitalii Tomkiv49dcaf22016-10-31 11:25:01 -070065 timings = None
Vitalii Tomkivabc92332016-09-20 11:55:44 -070066 while attempt <= MAX_RETRIES and processing_data is None:
67 attempt += 1
Vitalii Tomkiv49dcaf22016-10-31 11:25:01 -070068 processing_data, timings = iterate(
69 args, search_events, timing_events, cfg)
Vitalii Tomkivabc92332016-09-20 11:55:44 -070070
71 if processing_data is None:
72 # Processing error
73 print "Failed to collect valid samples for run {0}".format(it + 1)
74 continue
75 for k, v in processing_data.iteritems():
76 if k not in data_points:
77 data_points[k] = []
78 data_points[k].append(v['value'])
79
Vitalii Tomkiv49dcaf22016-10-31 11:25:01 -070080 if timings is not None:
81 for k, v in timings.iteritems():
82 if k not in timing_points:
83 timing_points[k] = []
84 timing_points[k].append(v)
85
Vitalii Tomkivabc92332016-09-20 11:55:44 -070086 if args.iterate > 1:
Vitalii Tomkiv49dcaf22016-10-31 11:25:01 -070087 if timing_points and args.timings:
88 print "Avg time values after {0} runs".format(args.iterate)
89 print '{0:30}: {1:<7} {2:<7}'.format("Event", "Mean", "stddev")
90
91 for item in sorted(timing_points.items(), key=operator.itemgetter(1)):
92 print '{0:30}: {1:<7.5} {2:<7.5}'.format(
93 item[0], sum(item[1])/len(item[1]), stddev(item[1]))
94
Vitalii Tomkivabc92332016-09-20 11:55:44 -070095 print "Avg values after {0} runs".format(args.iterate)
96 print '{0:30}: {1:<7} {2:<7}'.format("Event", "Mean", "stddev")
97
98 for item in sorted(data_points.items(), key=operator.itemgetter(1)):
99 print '{0:30}: {1:<7.5} {2:<7.5}'.format(
100 item[0], sum(item[1])/len(item[1]), stddev(item[1]))
101
Vitalii Tomkiv49dcaf22016-10-31 11:25:01 -0700102def iterate(args, search_events, timings, cfg):
Vitalii Tomkivabc92332016-09-20 11:55:44 -0700103 if args.reboot:
104 reboot()
105
Vitalii Tomkiv49dcaf22016-10-31 11:25:01 -0700106 logcat_events, logcat_timing_events = collect_events(
107 search_events, 'adb logcat -b all -v epoch', timings, cfg['stop_event'])
Vitalii Tomkived4c98c2016-04-28 15:20:57 -0700108
Vitalii Tomkiv49dcaf22016-10-31 11:25:01 -0700109 dmesg_events, e = collect_events(search_events, 'adb shell dmesg', {})
Vitalii Tomkived4c98c2016-04-28 15:20:57 -0700110
Vitalii Tomkivd704edd2016-07-13 17:27:03 -0700111 logcat_event_time = extract_time(
Vitalii Tomkiv49dcaf22016-10-31 11:25:01 -0700112 logcat_events, TIME_LOGCAT, float);
Vitalii Tomkivd704edd2016-07-13 17:27:03 -0700113 logcat_original_time = extract_time(
114 logcat_events, TIME_LOGCAT, str);
115 dmesg_event_time = extract_time(
116 dmesg_events, TIME_DMESG, float);
Vitalii Tomkived4c98c2016-04-28 15:20:57 -0700117
Vitalii Tomkivd704edd2016-07-13 17:27:03 -0700118 events = {}
119 diff_time = 0
120 max_time = 0
121 events_to_correct = []
122 replaced_from_dmesg = set()
Vitalii Tomkiv49dcaf22016-10-31 11:25:01 -0700123
124 time_correction_delta = 0
125 time_correction_time = 0
126 if ('time_correction_key' in cfg
127 and cfg['time_correction_key'] in logcat_events):
128 match = search_events[cfg['time_correction_key']].search(
129 logcat_events[cfg['time_correction_key']])
130 if match and logcat_event_time[cfg['time_correction_key']]:
131 time_correction_delta = float(match.group(1))
132 time_correction_time = logcat_event_time[cfg['time_correction_key']]
133
134 debug("time_correction_delta = {0}, time_correction_time = {1}".format(
135 time_correction_delta, time_correction_time))
136
Vitalii Tomkivd704edd2016-07-13 17:27:03 -0700137 for k, v in logcat_event_time.iteritems():
Vitalii Tomkiv49dcaf22016-10-31 11:25:01 -0700138 debug("event[{0}, {1}]".format(k, v))
139 if v <= time_correction_time:
140 logcat_event_time[k] += time_correction_delta
141 v = v + time_correction_delta
142 debug("correcting event to event[{0}, {1}]".format(k, v))
143
Vitalii Tomkivd704edd2016-07-13 17:27:03 -0700144 events[k] = v
145 if k in dmesg_event_time:
Vitalii Tomkiv49dcaf22016-10-31 11:25:01 -0700146 debug("{0} is in dmesg".format(k))
Vitalii Tomkivd704edd2016-07-13 17:27:03 -0700147 if dmesg_event_time[k] > max_time:
Vitalii Tomkiv49dcaf22016-10-31 11:25:01 -0700148 debug("{0} is bigger max={1}".format(dmesg_event_time[k], max_time))
Vitalii Tomkivd704edd2016-07-13 17:27:03 -0700149 max_time = dmesg_event_time[k]
150 diff_time = v - max_time
Vitalii Tomkiv49dcaf22016-10-31 11:25:01 -0700151 debug("diff_time={0}".format(diff_time))
Vitalii Tomkivd704edd2016-07-13 17:27:03 -0700152 events[k] = dmesg_event_time[k]
153 replaced_from_dmesg.add(k)
154 else:
155 events_to_correct.append(k)
156
Vitalii Tomkiv49dcaf22016-10-31 11:25:01 -0700157 debug("diff_time={0}".format(diff_time))
Vitalii Tomkivd704edd2016-07-13 17:27:03 -0700158 for k in events_to_correct:
Vitalii Tomkiv49dcaf22016-10-31 11:25:01 -0700159 debug("k={0}, {1}".format(k, events[k]))
160 if round(events[k] - diff_time, 3) >= 0:
161 events[k] = round(events[k] - diff_time, 3)
162 if events[k] > VALUE_TOO_BIG and not args.ignore:
Vitalii Tomkivabc92332016-09-20 11:55:44 -0700163 print "Event {0} value {1} too big , possible processing error".format(
164 k, events[k])
Vitalii Tomkiv49dcaf22016-10-31 11:25:01 -0700165 return None, None
Vitalii Tomkivabc92332016-09-20 11:55:44 -0700166
167 data_points = {}
Vitalii Tomkiv49dcaf22016-10-31 11:25:01 -0700168 timing_points = {}
169
170 if args.timings:
171 for k, l in logcat_timing_events.iteritems():
172 for v in l:
173 name, time_v = extract_timing(v, timings)
174 if name:
175 timing_points[name] = time_v
176 print "Event timing"
177 for item in sorted(timing_points.items(), key=operator.itemgetter(1)):
178 print '{0:30}: {1:<7.5}'.format(
179 item[0], item[1])
180 print "-----------------"
Vitalii Tomkivd704edd2016-07-13 17:27:03 -0700181
182 for item in sorted(events.items(), key=operator.itemgetter(1)):
Vitalii Tomkivabc92332016-09-20 11:55:44 -0700183 data_points[item[0]] = {
184 'value': item[1],
185 'from_dmesg': item[0] in replaced_from_dmesg,
186 'logcat_value': logcat_original_time[item[0]]
187 }
Vitalii Tomkivd704edd2016-07-13 17:27:03 -0700188 print '{0:30}: {1:<7.5} {2:1} ({3})'.format(
189 item[0], item[1], '*' if item[0] in replaced_from_dmesg else '',
190 logcat_original_time[item[0]])
191
Vitalii Tomkivabc92332016-09-20 11:55:44 -0700192 print '\n* - event time was obtained from dmesg log\n'
Vitalii Tomkiv49dcaf22016-10-31 11:25:01 -0700193 return data_points, timing_points
Vitalii Tomkivabc92332016-09-20 11:55:44 -0700194
Vitalii Tomkiv49dcaf22016-10-31 11:25:01 -0700195def debug(string):
196 if DEBUG:
197 print string
198
199def extract_timing(s, patterns):
200 for k, p in patterns.iteritems():
201 m = p.search(s)
202 if m:
203 g_dict = m.groupdict()
204 return g_dict['name'], float(g_dict['time'])
205 return None, Node
Vitalii Tomkivd704edd2016-07-13 17:27:03 -0700206
207def init_arguments():
208 parser = argparse.ArgumentParser(description='Measures boot time.')
209 parser.add_argument('-r', '--reboot', dest='reboot',
210 action='store_true',
211 help='adb reboot device for measurement', )
212 parser.add_argument('-c', '--config', dest='config',
213 default='config.yaml', type=argparse.FileType('r'),
214 help='config file for the tool', )
Vitalii Tomkivabc92332016-09-20 11:55:44 -0700215 parser.add_argument('-n', '--iterate', dest='iterate', type=int, default=1,
216 help='number of time to repeat the measurement', )
Vitalii Tomkiv49dcaf22016-10-31 11:25:01 -0700217 parser.add_argument('-g', '--ignore', dest='ignore', action='store_true',
218 help='ignore too big values error', )
219 parser.add_argument('-t', '--timings', dest='timings', action='store_true',
220 help='print individual component times', default=True, )
221
Vitalii Tomkivd704edd2016-07-13 17:27:03 -0700222 return parser.parse_args()
223
Vitalii Tomkiv49dcaf22016-10-31 11:25:01 -0700224def collect_events(search_events, command, timings, stop_event=None):
Vitalii Tomkivd704edd2016-07-13 17:27:03 -0700225 events = {}
Vitalii Tomkiv49dcaf22016-10-31 11:25:01 -0700226 timing_events = {}
Vitalii Tomkivd704edd2016-07-13 17:27:03 -0700227 process = subprocess.Popen(command, shell=True,
228 stdout=subprocess.PIPE);
229 out = process.stdout
230 data_available = stop_event is None
231 for line in out:
232 if not data_available:
233 print "Collecting data samples. Please wait...\n"
234 data_available = True
235 event = get_boot_event(line, search_events);
236 if event:
Vitalii Tomkiv49dcaf22016-10-31 11:25:01 -0700237 debug("event[{0}] captured: {1}".format(event, line))
Vitalii Tomkivd704edd2016-07-13 17:27:03 -0700238 events[event] = line
Vitalii Tomkiv49dcaf22016-10-31 11:25:01 -0700239
240 timing_event = get_boot_event(line, timings);
241 if timing_event:
242 if timing_event not in timing_events:
243 timing_events[timing_event] = []
244 timing_events[timing_event].append(line)
245 debug("timing_event[{0}] captured: {1}".format(timing_event, line))
246
Vitalii Tomkivd704edd2016-07-13 17:27:03 -0700247 if stop_event and stop_event in line:
248 break;
249 process.terminate()
Vitalii Tomkiv49dcaf22016-10-31 11:25:01 -0700250 return events, timing_events
Vitalii Tomkivd704edd2016-07-13 17:27:03 -0700251
252def get_boot_event(line, events):
253 for event_key, event_pattern in events.iteritems():
254 if event_pattern.search(line):
255 return event_key
Vitalii Tomkived4c98c2016-04-28 15:20:57 -0700256 return None
257
Vitalii Tomkivd704edd2016-07-13 17:27:03 -0700258def extract_time(events, pattern, date_transform_function):
259 result = {}
260 for event, data in events.iteritems():
261 found = re.findall(pattern, data)
Vitalii Tomkived4c98c2016-04-28 15:20:57 -0700262 if len(found) > 0:
Vitalii Tomkivd704edd2016-07-13 17:27:03 -0700263 result[event] = date_transform_function(found[0])
264 else:
265 print "Failed to find time for event: ", event, data
266 return result
Vitalii Tomkived4c98c2016-04-28 15:20:57 -0700267
Vitalii Tomkivd704edd2016-07-13 17:27:03 -0700268def reboot():
269 print 'Rebooting the device'
270 subprocess.Popen('adb reboot', shell=True).wait()
271
272def logcat_time_func(offset_year):
273 def f(date_str):
274 ndate = datetime.datetime.strptime(str(offset_year) + '-' +
275 date_str, '%Y-%m-%d %H:%M:%S.%f')
276 return datetime_to_unix_time(ndate)
277 return f
278
279
280def datetime_to_unix_time(ndate):
Vitalii Tomkived4c98c2016-04-28 15:20:57 -0700281 return time.mktime(ndate.timetuple()) + ndate.microsecond/1000000.0
282
Vitalii Tomkivabc92332016-09-20 11:55:44 -0700283def stddev(data):
284 items_count = len(data)
285 avg = sum(data) / items_count
286 sq_diffs_sum = sum([(v - avg) ** 2 for v in data])
287 variance = sq_diffs_sum / items_count
288 return math.sqrt(variance)
289
Vitalii Tomkived4c98c2016-04-28 15:20:57 -0700290if __name__ == '__main__':
291 main()