blob: 91e6c2bcbdd4d679c6495d383928dc941fedd5b0 [file] [log] [blame]
Yasuhiro Matsudaab379832015-07-03 02:08:55 +09001#!/usr/bin/env python
2# Copyright (C) 2015 The Android Open Source Project
3#
4# Licensed under the Apache License, Version 2.0 (the "License");
5# you may not use this file except in compliance with the License.
6# You may obtain a copy of the License at
7#
8# http://www.apache.org/licenses/LICENSE-2.0
9#
10# Unless required by applicable law or agreed to in writing, software
11# distributed under the License is distributed on an "AS IS" BASIS,
12# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13# See the License for the specific language governing permissions and
14# limitations under the License.
15"""Record the event logs during boot and output them to a file.
16
17This script repeats the record of each event log during Android boot specified
18times. By default, interval between measurements is adjusted in such a way that
19CPUs are cooled down sufficiently to avoid boot time slowdown caused by CPU
20thermal throttling. The result is output in a tab-separated value format.
21
22Examples:
23
24Repeat measurements 10 times. Interval between iterations is adjusted based on
25CPU temperature of the device.
26
27$ ./perfboot.py --iterations=10
28
29Repeat measurements 20 times. 60 seconds interval is taken between each
30iteration.
31
32$ ./perfboot.py --iterations=20 --interval=60
33
34Repeat measurements 20 times, show verbose output, output the result to
35data.tsv, and read event tags from eventtags.txt.
36
37$ ./perfboot.py --iterations=30 -v --output=data.tsv --tags=eventtags.txt
38"""
39
40import argparse
41import atexit
42import cStringIO
Yasuhiro Matsudac0822e82015-08-05 19:49:03 +090043import glob
Yasuhiro Matsudaab379832015-07-03 02:08:55 +090044import inspect
45import logging
46import math
47import os
48import re
49import subprocess
50import sys
51import threading
52import time
53
54sys.path.append(os.path.dirname(os.path.dirname(__file__)))
55import adb
56
57# The default event tags to record.
58_DEFAULT_EVENT_TAGS = [
59 'boot_progress_start',
60 'boot_progress_preload_start',
61 'boot_progress_preload_end',
62 'boot_progress_system_run',
63 'boot_progress_pms_start',
64 'boot_progress_pms_system_scan_start',
65 'boot_progress_pms_data_scan_start',
66 'boot_progress_pms_scan_end',
67 'boot_progress_pms_ready',
68 'boot_progress_ams_ready',
69 'boot_progress_enable_screen',
Yusuke Sato43c4d992015-08-04 12:05:45 -070070 'sf_stop_bootanim',
71 'wm_boot_animation_done',
Yasuhiro Matsudaab379832015-07-03 02:08:55 +090072]
73
74
75class IntervalAdjuster(object):
76 """A helper class to take suffficient interval between iterations."""
77
78 # CPU temperature values per product used to decide interval
79 _CPU_COOL_DOWN_THRESHOLDS = {
80 'flo': 40,
81 'flounder': 40000,
82 'razor': 40,
83 'volantis': 40000,
84 }
85 # The interval between CPU temperature checks
86 _CPU_COOL_DOWN_WAIT_INTERVAL = 10
87 # The wait time used when the value of _CPU_COOL_DOWN_THRESHOLDS for
88 # the product is not defined.
89 _CPU_COOL_DOWN_WAIT_TIME_DEFAULT = 120
90
91 def __init__(self, interval, device):
92 self._interval = interval
93 self._device = device
94 self._temp_paths = device.shell(
Yasuhiro Matsuda6ee19402015-09-15 14:00:10 +090095 ['ls', '/sys/class/thermal/thermal_zone*/temp'])[0].splitlines()
Yasuhiro Matsudaab379832015-07-03 02:08:55 +090096 self._product = device.get_prop('ro.build.product')
97 self._waited = False
98
99 def wait(self):
100 """Waits certain amount of time for CPUs cool-down."""
101 if self._interval is None:
102 self._wait_cpu_cool_down(self._product, self._temp_paths)
103 else:
104 if self._waited:
105 print 'Waiting for %d seconds' % self._interval
106 time.sleep(self._interval)
107 self._waited = True
108
109 def _get_cpu_temp(self, threshold):
110 max_temp = 0
111 for temp_path in self._temp_paths:
Yasuhiro Matsuda6ee19402015-09-15 14:00:10 +0900112 temp = int(self._device.shell(['cat', temp_path])[0].rstrip())
Yasuhiro Matsudaab379832015-07-03 02:08:55 +0900113 max_temp = max(max_temp, temp)
114 if temp >= threshold:
115 return temp
116 return max_temp
117
118 def _wait_cpu_cool_down(self, product, temp_paths):
119 threshold = IntervalAdjuster._CPU_COOL_DOWN_THRESHOLDS.get(
120 self._product)
121 if threshold is None:
122 print 'No CPU temperature threshold is set for ' + self._product
123 print ('Just wait %d seconds' %
124 IntervalAdjuster._CPU_COOL_DOWN_WAIT_TIME_DEFAULT)
125 time.sleep(IntervalAdjuster._CPU_COOL_DOWN_WAIT_TIME_DEFAULT)
126 return
127 while True:
128 temp = self._get_cpu_temp(threshold)
129 if temp < threshold:
130 logging.info('Current CPU temperature %s' % temp)
131 return
132 print 'Waiting until CPU temperature (%d) falls below %d' % (
133 temp, threshold)
134 time.sleep(IntervalAdjuster._CPU_COOL_DOWN_WAIT_INTERVAL)
135
136
137class WatchdogTimer(object):
138 """A timer that makes is_timedout() return true in |timeout| seconds."""
139 def __init__(self, timeout):
140 self._timedout = False
141
142 def notify_timeout():
143 self._timedout = True
144 self._timer = threading.Timer(timeout, notify_timeout)
Yasuhiro Matsuda59d32a72015-08-04 17:48:41 +0900145 self._timer.daemon = True
Yasuhiro Matsudaab379832015-07-03 02:08:55 +0900146 self._timer.start()
147
148 def is_timedout(self):
149 return self._timedout
150
151 def cancel(self):
152 self._timer.cancel()
153
154
155def readlines_unbuffered(proc):
156 """Read lines from |proc|'s standard out without buffering."""
157 while True:
158 buf = []
159 c = proc.stdout.read(1)
160 if c == '' and proc.poll() is not None:
161 break
162 while c != '\n':
163 if c == '' and proc.poll() is not None:
164 break
165 buf.append(c)
166 c = proc.stdout.read(1)
167 yield ''.join(buf)
168
169
170def disable_dropbox(device):
171 """Removes the files created by Dropbox and avoids creating the files."""
172 device.root()
173 device.wait()
174 device.shell(['rm', '-rf', '/system/data/dropbox'])
175 original_dropbox_max_files = device.shell(
Yasuhiro Matsuda6ee19402015-09-15 14:00:10 +0900176 ['settings', 'get', 'global', 'dropbox_max_files'])[0].rstrip()
Yasuhiro Matsudaab379832015-07-03 02:08:55 +0900177 device.shell(['settings', 'put', 'global', 'dropbox_max_files', '0'])
178 return original_dropbox_max_files
179
180
181def restore_dropbox(device, original_dropbox_max_files):
182 """Restores the dropbox_max_files setting."""
183 device.root()
184 device.wait()
185 if original_dropbox_max_files == 'null':
186 device.shell(['settings', 'delete', 'global', 'dropbox_max_files'])
187 else:
188 device.shell(['settings', 'put', 'global', 'dropbox_max_files',
189 original_dropbox_max_files])
190
191
192def init_perf(device, output, record_list, tags):
193 device.wait()
194 build_type = device.get_prop('ro.build.type')
195 original_dropbox_max_files = None
196 if build_type != 'user':
197 # Workaround for Dropbox issue (http://b/20890386).
198 original_dropbox_max_files = disable_dropbox(device)
199
200 def cleanup():
201 try:
202 if record_list:
203 print_summary(record_list, tags[-1])
204 output_results(output, record_list, tags)
205 if original_dropbox_max_files is not None:
206 restore_dropbox(device, original_dropbox_max_files)
Yasuhiro Matsudaf3d0d422015-08-05 20:26:03 +0900207 except (subprocess.CalledProcessError, RuntimeError):
Yasuhiro Matsudaab379832015-07-03 02:08:55 +0900208 pass
209 atexit.register(cleanup)
210
211
Yusuke Satob6c66dc2015-07-31 08:47:48 -0700212def check_dm_verity_settings(device):
213 device.wait()
214 for partition in ['system', 'vendor']:
215 verity_mode = device.get_prop('partition.%s.verified' % partition)
216 if verity_mode is None:
217 logging.warning('dm-verity is not enabled for /%s. Did you run '
218 'adb disable-verity? That may skew the result.',
219 partition)
220
221
Yasuhiro Matsudaab379832015-07-03 02:08:55 +0900222def read_event_tags(tags_file):
223 """Reads event tags from |tags_file|."""
224 if not tags_file:
225 return _DEFAULT_EVENT_TAGS
226 tags = []
227 with open(tags_file) as f:
228 for line in f:
229 if '#' in line:
230 line = line[:line.find('#')]
231 line = line.strip()
232 if line:
233 tags.append(line)
234 return tags
235
236
237def make_event_tags_re(tags):
238 """Makes a regular expression object that matches event logs of |tags|."""
239 return re.compile(r'(?P<pid>[0-9]+) +[0-9]+ I (?P<tag>%s): (?P<time>\d+)' %
240 '|'.join(tags))
241
242
Yusuke Satoe801cc02015-08-03 15:54:36 -0700243def filter_event_tags(tags, device):
244 """Drop unknown tags not listed in device's event-log-tags file."""
245 device.wait()
246 supported_tags = set()
Yasuhiro Matsuda6ee19402015-09-15 14:00:10 +0900247 for l in device.shell(
248 ['cat', '/system/etc/event-log-tags'])[0].splitlines():
Yusuke Satoe801cc02015-08-03 15:54:36 -0700249 tokens = l.split(' ')
250 if len(tokens) >= 2:
251 supported_tags.add(tokens[1])
252 filtered = []
253 for tag in tags:
254 if tag in supported_tags:
255 filtered.append(tag)
256 else:
257 logging.warning('Unknown tag \'%s\'. Ignoring...', tag)
258 return filtered
259
260
Yasuhiro Matsudaab379832015-07-03 02:08:55 +0900261def get_values(record, tag):
262 """Gets values that matches |tag| from |record|."""
263 keys = [key for key in record.keys() if key[0] == tag]
264 return [record[k] for k in sorted(keys)]
265
266
267def get_last_value(record, tag):
268 """Gets the last value that matches |tag| from |record|."""
269 values = get_values(record, tag)
270 if not values:
271 return 0
272 return values[-1]
273
274
275def output_results(filename, record_list, tags):
276 """Outputs |record_list| into |filename| in a TSV format."""
277 # First, count the number of the values of each tag.
278 # This is for dealing with events that occur multiple times.
279 # For instance, boot_progress_preload_start and boot_progress_preload_end
280 # are recorded twice on 64-bit system. One is for 64-bit zygote process
281 # and the other is for 32-bit zygote process.
282 values_counter = {}
283 for record in record_list:
284 for tag in tags:
285 # Some record might lack values for some tags due to unanticipated
286 # problems (e.g. timeout), so take the maximum count among all the
287 # record.
288 values_counter[tag] = max(values_counter.get(tag, 1),
289 len(get_values(record, tag)))
290
291 # Then creates labels for the data. If there are multiple values for one
292 # tag, labels for these values are numbered except the first one as
293 # follows:
294 #
295 # event_tag event_tag2 event_tag3
296 #
297 # The corresponding values are sorted in an ascending order of PID.
298 labels = []
299 for tag in tags:
300 for i in range(1, values_counter[tag] + 1):
301 labels.append('%s%s' % (tag, '' if i == 1 else str(i)))
302
303 # Finally write the data into the file.
304 with open(filename, 'w') as f:
305 f.write('\t'.join(labels) + '\n')
306 for record in record_list:
307 line = cStringIO.StringIO()
308 invalid_line = False
309 for i, tag in enumerate(tags):
310 if i != 0:
311 line.write('\t')
312 values = get_values(record, tag)
313 if len(values) < values_counter[tag]:
314 invalid_line = True
315 # Fill invalid record with 0
316 values += [0] * (values_counter[tag] - len(values))
317 line.write('\t'.join(str(t) for t in values))
318 if invalid_line:
319 logging.error('Invalid record found: ' + line.getvalue())
320 line.write('\n')
321 f.write(line.getvalue())
322 print 'Wrote: ' + filename
323
324
325def median(data):
326 """Calculates the median value from |data|."""
327 data = sorted(data)
328 n = len(data)
329 if n % 2 == 1:
330 return data[n / 2]
331 else:
332 n2 = n / 2
333 return (data[n2 - 1] + data[n2]) / 2.0
334
335
336def mean(data):
337 """Calculates the mean value from |data|."""
338 return float(sum(data)) / len(data)
339
340
341def stddev(data):
342 """Calculates the standard deviation value from |value|."""
343 m = mean(data)
344 return math.sqrt(sum((x - m) ** 2 for x in data) / len(data))
345
346
347def print_summary(record_list, end_tag):
348 """Prints the summary of |record_list|."""
349 # Filter out invalid data.
350 end_times = [get_last_value(record, end_tag) for record in record_list
351 if get_last_value(record, end_tag) != 0]
352 print 'mean: ', mean(end_times)
353 print 'median:', median(end_times)
354 print 'standard deviation:', stddev(end_times)
355
356
357def do_iteration(device, interval_adjuster, event_tags_re, end_tag):
358 """Measures the boot time once."""
359 device.wait()
360 interval_adjuster.wait()
361 device.reboot()
362 print 'Rebooted the device'
363 record = {}
364 booted = False
365 while not booted:
366 device.wait()
367 # Stop the iteration if it does not finish within 120 seconds.
368 timeout = 120
369 t = WatchdogTimer(timeout)
370 p = subprocess.Popen(
371 ['adb', 'logcat', '-b', 'events', '-v', 'threadtime'],
372 stdout=subprocess.PIPE)
373 for line in readlines_unbuffered(p):
374 if t.is_timedout():
375 print '*** Timed out ***'
376 return record
377 m = event_tags_re.search(line)
378 if not m:
379 continue
380 tag = m.group('tag')
381 event_time = int(m.group('time'))
382 pid = m.group('pid')
383 record[(tag, pid)] = event_time
384 print 'Event log recorded: %s (%s) - %d ms' % (
385 tag, pid, event_time)
386 if tag == end_tag:
387 booted = True
388 t.cancel()
389 break
390 return record
391
392
393def parse_args():
394 """Parses the command line arguments."""
395 parser = argparse.ArgumentParser(
396 description=inspect.getdoc(sys.modules[__name__]),
397 formatter_class=argparse.RawDescriptionHelpFormatter)
398 parser.add_argument('--iterations', type=int, default=5,
399 help='Number of times to repeat boot measurements.')
400 parser.add_argument('--interval', type=int,
401 help=('Duration between iterations. If this is not '
402 'set explicitly, durations are determined '
403 'adaptively based on CPUs temperature.'))
404 parser.add_argument('-o', '--output', help='File name of output data.')
405 parser.add_argument('-v', '--verbose', action='store_true',
406 help='Show verbose output.')
407 parser.add_argument('-s', '--serial', default=os.getenv('ANDROID_SERIAL'),
408 help='Adb device serial number.')
409 parser.add_argument('-t', '--tags', help='Specify the filename from which '
410 'event tags are read. Every line contains one event '
411 'tag and the last event tag is used to detect that '
Yusuke Sato3966ebb2015-08-17 17:26:10 -0700412 'the device has finished booting unless --end-tag is '
413 'specified.')
414 parser.add_argument('--end-tag', help='An event tag on which the script '
415 'stops measuring the boot time.')
Yasuhiro Matsudac0822e82015-08-05 19:49:03 +0900416 parser.add_argument('--apk-dir', help='Specify the directory which contains '
417 'APK files to be installed before measuring boot time.')
Yasuhiro Matsudaab379832015-07-03 02:08:55 +0900418 return parser.parse_args()
419
420
Yasuhiro Matsudac0822e82015-08-05 19:49:03 +0900421def install_apks(device, apk_dir):
422 for apk in glob.glob(os.path.join(apk_dir, '*.apk')):
423 print 'Installing: ' + apk
424 device.install(apk, replace=True)
425
426
Yasuhiro Matsudaab379832015-07-03 02:08:55 +0900427def main():
428 args = parse_args()
429 if args.verbose:
430 logging.getLogger().setLevel(logging.INFO)
431
432 device = adb.get_device(args.serial)
433
434 if not args.output:
435 device.wait()
436 args.output = 'perf-%s-%s.tsv' % (
437 device.get_prop('ro.build.flavor'),
438 device.get_prop('ro.build.version.incremental'))
Yusuke Satob6c66dc2015-07-31 08:47:48 -0700439 check_dm_verity_settings(device)
Yasuhiro Matsudaab379832015-07-03 02:08:55 +0900440
Yasuhiro Matsudac0822e82015-08-05 19:49:03 +0900441 if args.apk_dir:
442 install_apks(device, args.apk_dir)
443
Yasuhiro Matsudaab379832015-07-03 02:08:55 +0900444 record_list = []
Yusuke Satoe801cc02015-08-03 15:54:36 -0700445 event_tags = filter_event_tags(read_event_tags(args.tags), device)
Yusuke Sato3966ebb2015-08-17 17:26:10 -0700446 end_tag = args.end_tag or event_tags[-1]
447 if end_tag not in event_tags:
448 sys.exit('%s is not a valid tag.' % end_tag)
449 event_tags = event_tags[0 : event_tags.index(end_tag) + 1]
Yasuhiro Matsudaab379832015-07-03 02:08:55 +0900450 init_perf(device, args.output, record_list, event_tags)
451 interval_adjuster = IntervalAdjuster(args.interval, device)
452 event_tags_re = make_event_tags_re(event_tags)
Yusuke Sato3966ebb2015-08-17 17:26:10 -0700453
Yasuhiro Matsudaab379832015-07-03 02:08:55 +0900454 for i in range(args.iterations):
455 print 'Run #%d ' % i
456 record = do_iteration(
457 device, interval_adjuster, event_tags_re, end_tag)
458 record_list.append(record)
459
460
461if __name__ == '__main__':
462 main()