• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
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 glob
44import 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',
70    'sf_stop_bootanim',
71    'wm_boot_animation_done',
72]
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(
95            ['ls', '/sys/class/thermal/thermal_zone*/temp'])[0].splitlines()
96        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:
112            temp = int(self._device.shell(['cat', temp_path])[0].rstrip())
113            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)
145        self._timer.daemon = True
146        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(
176        ['settings', 'get', 'global', 'dropbox_max_files'])[0].rstrip()
177    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)
207        except (subprocess.CalledProcessError, RuntimeError):
208            pass
209    atexit.register(cleanup)
210
211
212def 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
222def 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
243def 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()
247    for l in device.shell(
248        ['cat', '/system/etc/event-log-tags'])[0].splitlines():
249        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
261def 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 '
412                        '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.')
416    parser.add_argument('--apk-dir', help='Specify the directory which contains '
417                        'APK files to be installed before measuring boot time.')
418    return parser.parse_args()
419
420
421def 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
427def 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'))
439    check_dm_verity_settings(device)
440
441    if args.apk_dir:
442        install_apks(device, args.apk_dir)
443
444    record_list = []
445    event_tags = filter_event_tags(read_event_tags(args.tags), device)
446    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]
450    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)
453
454    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()
463