Home | History | Annotate | Download | only in init 
      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 glob
     44 import inspect
     45 import logging
     46 import math
     47 import os
     48 import re
     49 import subprocess
     50 import sys
     51 import threading
     52 import time
     53 
     54 sys.path.append(os.path.dirname(os.path.dirname(__file__)))
     55 import 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 
     75 class 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 
    137 class 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 
    155 def 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 
    170 def 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 
    181 def 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 
    192 def init_perf(device, output, record_list, tags):
    193     device.wait()
    194     debuggable = device.get_prop('ro.debuggable')
    195     original_dropbox_max_files = None
    196     if debuggable == '1':
    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 
    212 def 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 
    222 def 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 
    237 def 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 
    243 def 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 
    261 def 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 
    267 def 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 
    275 def 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 
    325 def 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 
    336 def mean(data):
    337     """Calculates the mean value from |data|."""
    338     return float(sum(data)) / len(data)
    339 
    340 
    341 def 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 
    347 def 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 
    357 def 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 
    393 def 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 
    421 def 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 
    427 def 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 
    461 if __name__ == '__main__':
    462     main()
    463