diff options
-rw-r--r-- | adb/device.py | 7 | ||||
-rwxr-xr-x | init/perfboot.py | 411 |
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 | # |
16 | import logging | ||
16 | import os | 17 | import os |
17 | import re | 18 | import re |
18 | import subprocess | 19 | import 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 | |||
17 | This script repeats the record of each event log during Android boot specified | ||
18 | times. By default, interval between measurements is adjusted in such a way that | ||
19 | CPUs are cooled down sufficiently to avoid boot time slowdown caused by CPU | ||
20 | thermal throttling. The result is output in a tab-separated value format. | ||
21 | |||
22 | Examples: | ||
23 | |||
24 | Repeat measurements 10 times. Interval between iterations is adjusted based on | ||
25 | CPU temperature of the device. | ||
26 | |||
27 | $ ./perfboot.py --iterations=10 | ||
28 | |||
29 | Repeat measurements 20 times. 60 seconds interval is taken between each | ||
30 | iteration. | ||
31 | |||
32 | $ ./perfboot.py --iterations=20 --interval=60 | ||
33 | |||
34 | Repeat measurements 20 times, show verbose output, output the result to | ||
35 | data.tsv, and read event tags from eventtags.txt. | ||
36 | |||
37 | $ ./perfboot.py --iterations=30 -v --output=data.tsv --tags=eventtags.txt | ||
38 | """ | ||
39 | |||
40 | import argparse | ||
41 | import atexit | ||
42 | import cStringIO | ||
43 | import inspect | ||
44 | import logging | ||
45 | import math | ||
46 | import os | ||
47 | import re | ||
48 | import subprocess | ||
49 | import sys | ||
50 | import threading | ||
51 | import time | ||
52 | |||
53 | sys.path.append(os.path.dirname(os.path.dirname(__file__))) | ||
54 | import 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 | |||
72 | class 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 | |||
134 | class 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 | |||
151 | def 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 | |||
166 | def 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 | |||
177 | def 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 | |||
188 | def 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 | |||
208 | def 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 | |||
223 | def 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 | |||
229 | def 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 | |||
235 | def 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 | |||
243 | def 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 | |||
293 | def 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 | |||
304 | def mean(data): | ||
305 | """Calculates the mean value from |data|.""" | ||
306 | return float(sum(data)) / len(data) | ||
307 | |||
308 | |||
309 | def 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 | |||
315 | def 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 | |||
325 | def 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 | |||
361 | def 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 | |||
384 | def 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 | |||
410 | if __name__ == '__main__': | ||
411 | main() | ||