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 @@ # See the License for the specific language governing permissions and # limitations under the License. # +import logging import os import re import subprocess @@ -146,10 +147,12 @@ class AndroidDevice(object): return result, out def _simple_call(self, cmd): + logging.info(' '.join(self.adb_cmd + cmd)) return subprocess.check_output( self.adb_cmd + cmd, stderr=subprocess.STDOUT) def shell(self, cmd): + logging.info(' '.join(self.adb_cmd + ['shell'] + cmd)) cmd = self._make_shell_cmd(cmd) out = subprocess.check_output(cmd) rc, out = self._parse_shell_output(out) @@ -161,6 +164,7 @@ class AndroidDevice(object): def shell_nocheck(self, cmd): cmd = self._make_shell_cmd(cmd) + logging.info(' '.join(cmd)) p = subprocess.Popen( cmd, stdout=subprocess.PIPE, stderr=subprocess.STDOUT) out, _ = p.communicate() @@ -190,6 +194,9 @@ class AndroidDevice(object): def usb(self): return self._simple_call(['usb']) + def reboot(self): + return self._simple_call(['reboot']) + def root(self): return self._simple_call(['root']) 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 @@ +#!/usr/bin/env python +# Copyright (C) 2015 The Android Open Source Project +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. +"""Record the event logs during boot and output them to a file. + +This script repeats the record of each event log during Android boot specified +times. By default, interval between measurements is adjusted in such a way that +CPUs are cooled down sufficiently to avoid boot time slowdown caused by CPU +thermal throttling. The result is output in a tab-separated value format. + +Examples: + +Repeat measurements 10 times. Interval between iterations is adjusted based on +CPU temperature of the device. + +$ ./perfboot.py --iterations=10 + +Repeat measurements 20 times. 60 seconds interval is taken between each +iteration. + +$ ./perfboot.py --iterations=20 --interval=60 + +Repeat measurements 20 times, show verbose output, output the result to +data.tsv, and read event tags from eventtags.txt. + +$ ./perfboot.py --iterations=30 -v --output=data.tsv --tags=eventtags.txt +""" + +import argparse +import atexit +import cStringIO +import inspect +import logging +import math +import os +import re +import subprocess +import sys +import threading +import time + +sys.path.append(os.path.dirname(os.path.dirname(__file__))) +import adb + +# The default event tags to record. +_DEFAULT_EVENT_TAGS = [ + 'boot_progress_start', + 'boot_progress_preload_start', + 'boot_progress_preload_end', + 'boot_progress_system_run', + 'boot_progress_pms_start', + 'boot_progress_pms_system_scan_start', + 'boot_progress_pms_data_scan_start', + 'boot_progress_pms_scan_end', + 'boot_progress_pms_ready', + 'boot_progress_ams_ready', + 'boot_progress_enable_screen', +] + + +class IntervalAdjuster(object): + """A helper class to take suffficient interval between iterations.""" + + # CPU temperature values per product used to decide interval + _CPU_COOL_DOWN_THRESHOLDS = { + 'flo': 40, + 'flounder': 40000, + 'razor': 40, + 'volantis': 40000, + } + # The interval between CPU temperature checks + _CPU_COOL_DOWN_WAIT_INTERVAL = 10 + # The wait time used when the value of _CPU_COOL_DOWN_THRESHOLDS for + # the product is not defined. + _CPU_COOL_DOWN_WAIT_TIME_DEFAULT = 120 + + def __init__(self, interval, device): + self._interval = interval + self._device = device + self._temp_paths = device.shell( + ['ls', '/sys/class/thermal/thermal_zone*/temp']).splitlines() + self._product = device.get_prop('ro.build.product') + self._waited = False + + def wait(self): + """Waits certain amount of time for CPUs cool-down.""" + if self._interval is None: + self._wait_cpu_cool_down(self._product, self._temp_paths) + else: + if self._waited: + print 'Waiting for %d seconds' % self._interval + time.sleep(self._interval) + self._waited = True + + def _get_cpu_temp(self, threshold): + max_temp = 0 + for temp_path in self._temp_paths: + temp = int(self._device.shell(['cat', temp_path]).rstrip()) + max_temp = max(max_temp, temp) + if temp >= threshold: + return temp + return max_temp + + def _wait_cpu_cool_down(self, product, temp_paths): + threshold = IntervalAdjuster._CPU_COOL_DOWN_THRESHOLDS.get( + self._product) + if threshold is None: + print 'No CPU temperature threshold is set for ' + self._product + print ('Just wait %d seconds' % + IntervalAdjuster._CPU_COOL_DOWN_WAIT_TIME_DEFAULT) + time.sleep(IntervalAdjuster._CPU_COOL_DOWN_WAIT_TIME_DEFAULT) + return + while True: + temp = self._get_cpu_temp(threshold) + if temp < threshold: + logging.info('Current CPU temperature %s' % temp) + return + print 'Waiting until CPU temperature (%d) falls below %d' % ( + temp, threshold) + time.sleep(IntervalAdjuster._CPU_COOL_DOWN_WAIT_INTERVAL) + + +class WatchdogTimer(object): + """A timer that makes is_timedout() return true in |timeout| seconds.""" + def __init__(self, timeout): + self._timedout = False + + def notify_timeout(): + self._timedout = True + self._timer = threading.Timer(timeout, notify_timeout) + self._timer.start() + + def is_timedout(self): + return self._timedout + + def cancel(self): + self._timer.cancel() + + +def readlines_unbuffered(proc): + """Read lines from |proc|'s standard out without buffering.""" + while True: + buf = [] + c = proc.stdout.read(1) + if c == '' and proc.poll() is not None: + break + while c != '\n': + if c == '' and proc.poll() is not None: + break + buf.append(c) + c = proc.stdout.read(1) + yield ''.join(buf) + + +def disable_dropbox(device): + """Removes the files created by Dropbox and avoids creating the files.""" + device.root() + device.wait() + device.shell(['rm', '-rf', '/system/data/dropbox']) + original_dropbox_max_files = device.shell( + ['settings', 'get', 'global', 'dropbox_max_files']).rstrip() + device.shell(['settings', 'put', 'global', 'dropbox_max_files', '0']) + return original_dropbox_max_files + + +def restore_dropbox(device, original_dropbox_max_files): + """Restores the dropbox_max_files setting.""" + device.root() + device.wait() + if original_dropbox_max_files == 'null': + device.shell(['settings', 'delete', 'global', 'dropbox_max_files']) + else: + device.shell(['settings', 'put', 'global', 'dropbox_max_files', + original_dropbox_max_files]) + + +def init_perf(device, output, record_list, tags): + device.wait() + build_type = device.get_prop('ro.build.type') + original_dropbox_max_files = None + if build_type != 'user': + # Workaround for Dropbox issue (http://b/20890386). + original_dropbox_max_files = disable_dropbox(device) + + def cleanup(): + try: + if record_list: + print_summary(record_list, tags[-1]) + output_results(output, record_list, tags) + if original_dropbox_max_files is not None: + restore_dropbox(device, original_dropbox_max_files) + except subprocess.CalledProcessError, RuntimeError: + pass + atexit.register(cleanup) + + +def read_event_tags(tags_file): + """Reads event tags from |tags_file|.""" + if not tags_file: + return _DEFAULT_EVENT_TAGS + tags = [] + with open(tags_file) as f: + for line in f: + if '#' in line: + line = line[:line.find('#')] + line = line.strip() + if line: + tags.append(line) + return tags + + +def make_event_tags_re(tags): + """Makes a regular expression object that matches event logs of |tags|.""" + return re.compile(r'(?P[0-9]+) +[0-9]+ I (?P%s): (?P