summaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
-rw-r--r--adb/device.py7
-rwxr-xr-xinit/perfboot.py411
2 files changed, 418 insertions, 0 deletions
diff --git a/adb/device.py b/adb/device.py
index 57f17fc78..b6eaad63f 100644
--- a/adb/device.py
+++ b/adb/device.py
@@ -13,6 +13,7 @@
13# See the License for the specific language governing permissions and 13# See the License for the specific language governing permissions and
14# limitations under the License. 14# limitations under the License.
15# 15#
16import logging
16import os 17import os
17import re 18import re
18import subprocess 19import subprocess
@@ -146,10 +147,12 @@ class AndroidDevice(object):
146 return result, out 147 return result, out
147 148
148 def _simple_call(self, cmd): 149 def _simple_call(self, cmd):
150 logging.info(' '.join(self.adb_cmd + cmd))
149 return subprocess.check_output( 151 return subprocess.check_output(
150 self.adb_cmd + cmd, stderr=subprocess.STDOUT) 152 self.adb_cmd + cmd, stderr=subprocess.STDOUT)
151 153
152 def shell(self, cmd): 154 def shell(self, cmd):
155 logging.info(' '.join(self.adb_cmd + ['shell'] + cmd))
153 cmd = self._make_shell_cmd(cmd) 156 cmd = self._make_shell_cmd(cmd)
154 out = subprocess.check_output(cmd) 157 out = subprocess.check_output(cmd)
155 rc, out = self._parse_shell_output(out) 158 rc, out = self._parse_shell_output(out)
@@ -161,6 +164,7 @@ class AndroidDevice(object):
161 164
162 def shell_nocheck(self, cmd): 165 def shell_nocheck(self, cmd):
163 cmd = self._make_shell_cmd(cmd) 166 cmd = self._make_shell_cmd(cmd)
167 logging.info(' '.join(cmd))
164 p = subprocess.Popen( 168 p = subprocess.Popen(
165 cmd, stdout=subprocess.PIPE, stderr=subprocess.STDOUT) 169 cmd, stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
166 out, _ = p.communicate() 170 out, _ = p.communicate()
@@ -190,6 +194,9 @@ class AndroidDevice(object):
190 def usb(self): 194 def usb(self):
191 return self._simple_call(['usb']) 195 return self._simple_call(['usb'])
192 196
197 def reboot(self):
198 return self._simple_call(['reboot'])
199
193 def root(self): 200 def root(self):
194 return self._simple_call(['root']) 201 return self._simple_call(['root'])
195 202
diff --git a/init/perfboot.py b/init/perfboot.py
new file mode 100755
index 000000000..2cd469925
--- /dev/null
+++ b/init/perfboot.py
@@ -0,0 +1,411 @@
1#!/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
43import inspect
44import logging
45import math
46import os
47import re
48import subprocess
49import sys
50import threading
51import time
52
53sys.path.append(os.path.dirname(os.path.dirname(__file__)))
54import adb
55
56# The default event tags to record.
57_DEFAULT_EVENT_TAGS = [
58 'boot_progress_start',
59 'boot_progress_preload_start',
60 'boot_progress_preload_end',
61 'boot_progress_system_run',
62 'boot_progress_pms_start',
63 'boot_progress_pms_system_scan_start',
64 'boot_progress_pms_data_scan_start',
65 'boot_progress_pms_scan_end',
66 'boot_progress_pms_ready',
67 'boot_progress_ams_ready',
68 'boot_progress_enable_screen',
69]
70
71
72class IntervalAdjuster(object):
73 """A helper class to take suffficient interval between iterations."""
74
75 # CPU temperature values per product used to decide interval
76 _CPU_COOL_DOWN_THRESHOLDS = {
77 'flo': 40,
78 'flounder': 40000,
79 'razor': 40,
80 'volantis': 40000,
81 }
82 # The interval between CPU temperature checks
83 _CPU_COOL_DOWN_WAIT_INTERVAL = 10
84 # The wait time used when the value of _CPU_COOL_DOWN_THRESHOLDS for
85 # the product is not defined.
86 _CPU_COOL_DOWN_WAIT_TIME_DEFAULT = 120
87
88 def __init__(self, interval, device):
89 self._interval = interval
90 self._device = device
91 self._temp_paths = device.shell(
92 ['ls', '/sys/class/thermal/thermal_zone*/temp']).splitlines()
93 self._product = device.get_prop('ro.build.product')
94 self._waited = False
95
96 def wait(self):
97 """Waits certain amount of time for CPUs cool-down."""
98 if self._interval is None:
99 self._wait_cpu_cool_down(self._product, self._temp_paths)
100 else:
101 if self._waited:
102 print 'Waiting for %d seconds' % self._interval
103 time.sleep(self._interval)
104 self._waited = True
105
106 def _get_cpu_temp(self, threshold):
107 max_temp = 0
108 for temp_path in self._temp_paths:
109 temp = int(self._device.shell(['cat', temp_path]).rstrip())
110 max_temp = max(max_temp, temp)
111 if temp >= threshold:
112 return temp
113 return max_temp
114
115 def _wait_cpu_cool_down(self, product, temp_paths):
116 threshold = IntervalAdjuster._CPU_COOL_DOWN_THRESHOLDS.get(
117 self._product)
118 if threshold is None:
119 print 'No CPU temperature threshold is set for ' + self._product
120 print ('Just wait %d seconds' %
121 IntervalAdjuster._CPU_COOL_DOWN_WAIT_TIME_DEFAULT)
122 time.sleep(IntervalAdjuster._CPU_COOL_DOWN_WAIT_TIME_DEFAULT)
123 return
124 while True:
125 temp = self._get_cpu_temp(threshold)
126 if temp < threshold:
127 logging.info('Current CPU temperature %s' % temp)
128 return
129 print 'Waiting until CPU temperature (%d) falls below %d' % (
130 temp, threshold)
131 time.sleep(IntervalAdjuster._CPU_COOL_DOWN_WAIT_INTERVAL)
132
133
134class WatchdogTimer(object):
135 """A timer that makes is_timedout() return true in |timeout| seconds."""
136 def __init__(self, timeout):
137 self._timedout = False
138
139 def notify_timeout():
140 self._timedout = True
141 self._timer = threading.Timer(timeout, notify_timeout)
142 self._timer.start()
143
144 def is_timedout(self):
145 return self._timedout
146
147 def cancel(self):
148 self._timer.cancel()
149
150
151def readlines_unbuffered(proc):
152 """Read lines from |proc|'s standard out without buffering."""
153 while True:
154 buf = []
155 c = proc.stdout.read(1)
156 if c == '' and proc.poll() is not None:
157 break
158 while c != '\n':
159 if c == '' and proc.poll() is not None:
160 break
161 buf.append(c)
162 c = proc.stdout.read(1)
163 yield ''.join(buf)
164
165
166def disable_dropbox(device):
167 """Removes the files created by Dropbox and avoids creating the files."""
168 device.root()
169 device.wait()
170 device.shell(['rm', '-rf', '/system/data/dropbox'])
171 original_dropbox_max_files = device.shell(
172 ['settings', 'get', 'global', 'dropbox_max_files']).rstrip()
173 device.shell(['settings', 'put', 'global', 'dropbox_max_files', '0'])
174 return original_dropbox_max_files
175
176
177def restore_dropbox(device, original_dropbox_max_files):
178 """Restores the dropbox_max_files setting."""
179 device.root()
180 device.wait()
181 if original_dropbox_max_files == 'null':
182 device.shell(['settings', 'delete', 'global', 'dropbox_max_files'])
183 else:
184 device.shell(['settings', 'put', 'global', 'dropbox_max_files',
185 original_dropbox_max_files])
186
187
188def init_perf(device, output, record_list, tags):
189 device.wait()
190 build_type = device.get_prop('ro.build.type')
191 original_dropbox_max_files = None
192 if build_type != 'user':
193 # Workaround for Dropbox issue (http://b/20890386).
194 original_dropbox_max_files = disable_dropbox(device)
195
196 def cleanup():
197 try:
198 if record_list:
199 print_summary(record_list, tags[-1])
200 output_results(output, record_list, tags)
201 if original_dropbox_max_files is not None:
202 restore_dropbox(device, original_dropbox_max_files)
203 except subprocess.CalledProcessError, RuntimeError:
204 pass
205 atexit.register(cleanup)
206
207
208def read_event_tags(tags_file):
209 """Reads event tags from |tags_file|."""
210 if not tags_file:
211 return _DEFAULT_EVENT_TAGS
212 tags = []
213 with open(tags_file) as f:
214 for line in f:
215 if '#' in line:
216 line = line[:line.find('#')]
217 line = line.strip()
218 if line:
219 tags.append(line)
220 return tags
221
222
223def make_event_tags_re(tags):
224 """Makes a regular expression object that matches event logs of |tags|."""
225 return re.compile(r'(?P<pid>[0-9]+) +[0-9]+ I (?P<tag>%s): (?P<time>\d+)' %
226 '|'.join(tags))
227
228
229def get_values(record, tag):
230 """Gets values that matches |tag| from |record|."""
231 keys = [key for key in record.keys() if key[0] == tag]
232 return [record[k] for k in sorted(keys)]
233
234
235def get_last_value(record, tag):
236 """Gets the last value that matches |tag| from |record|."""
237 values = get_values(record, tag)
238 if not values:
239 return 0
240 return values[-1]
241
242
243def output_results(filename, record_list, tags):
244 """Outputs |record_list| into |filename| in a TSV format."""
245 # First, count the number of the values of each tag.
246 # This is for dealing with events that occur multiple times.
247 # For instance, boot_progress_preload_start and boot_progress_preload_end
248 # are recorded twice on 64-bit system. One is for 64-bit zygote process
249 # and the other is for 32-bit zygote process.
250 values_counter = {}
251 for record in record_list:
252 for tag in tags:
253 # Some record might lack values for some tags due to unanticipated
254 # problems (e.g. timeout), so take the maximum count among all the
255 # record.
256 values_counter[tag] = max(values_counter.get(tag, 1),
257 len(get_values(record, tag)))
258
259 # Then creates labels for the data. If there are multiple values for one
260 # tag, labels for these values are numbered except the first one as
261 # follows:
262 #
263 # event_tag event_tag2 event_tag3
264 #
265 # The corresponding values are sorted in an ascending order of PID.
266 labels = []
267 for tag in tags:
268 for i in range(1, values_counter[tag] + 1):
269 labels.append('%s%s' % (tag, '' if i == 1 else str(i)))
270
271 # Finally write the data into the file.
272 with open(filename, 'w') as f:
273 f.write('\t'.join(labels) + '\n')
274 for record in record_list:
275 line = cStringIO.StringIO()
276 invalid_line = False
277 for i, tag in enumerate(tags):
278 if i != 0:
279 line.write('\t')
280 values = get_values(record, tag)
281 if len(values) < values_counter[tag]:
282 invalid_line = True
283 # Fill invalid record with 0
284 values += [0] * (values_counter[tag] - len(values))
285 line.write('\t'.join(str(t) for t in values))
286 if invalid_line:
287 logging.error('Invalid record found: ' + line.getvalue())
288 line.write('\n')
289 f.write(line.getvalue())
290 print 'Wrote: ' + filename
291
292
293def median(data):
294 """Calculates the median value from |data|."""
295 data = sorted(data)
296 n = len(data)
297 if n % 2 == 1:
298 return data[n / 2]
299 else:
300 n2 = n / 2
301 return (data[n2 - 1] + data[n2]) / 2.0
302
303
304def mean(data):
305 """Calculates the mean value from |data|."""
306 return float(sum(data)) / len(data)
307
308
309def stddev(data):
310 """Calculates the standard deviation value from |value|."""
311 m = mean(data)
312 return math.sqrt(sum((x - m) ** 2 for x in data) / len(data))
313
314
315def print_summary(record_list, end_tag):
316 """Prints the summary of |record_list|."""
317 # Filter out invalid data.
318 end_times = [get_last_value(record, end_tag) for record in record_list
319 if get_last_value(record, end_tag) != 0]
320 print 'mean: ', mean(end_times)
321 print 'median:', median(end_times)
322 print 'standard deviation:', stddev(end_times)
323
324
325def do_iteration(device, interval_adjuster, event_tags_re, end_tag):
326 """Measures the boot time once."""
327 device.wait()
328 interval_adjuster.wait()
329 device.reboot()
330 print 'Rebooted the device'
331 record = {}
332 booted = False
333 while not booted:
334 device.wait()
335 # Stop the iteration if it does not finish within 120 seconds.
336 timeout = 120
337 t = WatchdogTimer(timeout)
338 p = subprocess.Popen(
339 ['adb', 'logcat', '-b', 'events', '-v', 'threadtime'],
340 stdout=subprocess.PIPE)
341 for line in readlines_unbuffered(p):
342 if t.is_timedout():
343 print '*** Timed out ***'
344 return record
345 m = event_tags_re.search(line)
346 if not m:
347 continue
348 tag = m.group('tag')
349 event_time = int(m.group('time'))
350 pid = m.group('pid')
351 record[(tag, pid)] = event_time
352 print 'Event log recorded: %s (%s) - %d ms' % (
353 tag, pid, event_time)
354 if tag == end_tag:
355 booted = True
356 t.cancel()
357 break
358 return record
359
360
361def parse_args():
362 """Parses the command line arguments."""
363 parser = argparse.ArgumentParser(
364 description=inspect.getdoc(sys.modules[__name__]),
365 formatter_class=argparse.RawDescriptionHelpFormatter)
366 parser.add_argument('--iterations', type=int, default=5,
367 help='Number of times to repeat boot measurements.')
368 parser.add_argument('--interval', type=int,
369 help=('Duration between iterations. If this is not '
370 'set explicitly, durations are determined '
371 'adaptively based on CPUs temperature.'))
372 parser.add_argument('-o', '--output', help='File name of output data.')
373 parser.add_argument('-v', '--verbose', action='store_true',
374 help='Show verbose output.')
375 parser.add_argument('-s', '--serial', default=os.getenv('ANDROID_SERIAL'),
376 help='Adb device serial number.')
377 parser.add_argument('-t', '--tags', help='Specify the filename from which '
378 'event tags are read. Every line contains one event '
379 'tag and the last event tag is used to detect that '
380 'the device has finished booting.')
381 return parser.parse_args()
382
383
384def main():
385 args = parse_args()
386 if args.verbose:
387 logging.getLogger().setLevel(logging.INFO)
388
389 device = adb.get_device(args.serial)
390
391 if not args.output:
392 device.wait()
393 args.output = 'perf-%s-%s.tsv' % (
394 device.get_prop('ro.build.flavor'),
395 device.get_prop('ro.build.version.incremental'))
396
397 record_list = []
398 event_tags = read_event_tags(args.tags)
399 init_perf(device, args.output, record_list, event_tags)
400 interval_adjuster = IntervalAdjuster(args.interval, device)
401 event_tags_re = make_event_tags_re(event_tags)
402 end_tag = event_tags[-1]
403 for i in range(args.iterations):
404 print 'Run #%d ' % i
405 record = do_iteration(
406 device, interval_adjuster, event_tags_re, end_tag)
407 record_list.append(record)
408
409
410if __name__ == '__main__':
411 main()