am 1a1f9beb: am dcf89091: Merge "Add a script to record Android boot time."
* commit '1a1f9beb1dbd0da0f305ff44816661cc404ba877':
Add a script to record Android boot time.
diff --git a/adb/device.py b/adb/device.py
index 57f17fc..b6eaad6 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 @@
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 @@
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 @@
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 0000000..2cd4699
--- /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<pid>[0-9]+) +[0-9]+ I (?P<tag>%s): (?P<time>\d+)' %
+ '|'.join(tags))
+
+
+def get_values(record, tag):
+ """Gets values that matches |tag| from |record|."""
+ keys = [key for key in record.keys() if key[0] == tag]
+ return [record[k] for k in sorted(keys)]
+
+
+def get_last_value(record, tag):
+ """Gets the last value that matches |tag| from |record|."""
+ values = get_values(record, tag)
+ if not values:
+ return 0
+ return values[-1]
+
+
+def output_results(filename, record_list, tags):
+ """Outputs |record_list| into |filename| in a TSV format."""
+ # First, count the number of the values of each tag.
+ # This is for dealing with events that occur multiple times.
+ # For instance, boot_progress_preload_start and boot_progress_preload_end
+ # are recorded twice on 64-bit system. One is for 64-bit zygote process
+ # and the other is for 32-bit zygote process.
+ values_counter = {}
+ for record in record_list:
+ for tag in tags:
+ # Some record might lack values for some tags due to unanticipated
+ # problems (e.g. timeout), so take the maximum count among all the
+ # record.
+ values_counter[tag] = max(values_counter.get(tag, 1),
+ len(get_values(record, tag)))
+
+ # Then creates labels for the data. If there are multiple values for one
+ # tag, labels for these values are numbered except the first one as
+ # follows:
+ #
+ # event_tag event_tag2 event_tag3
+ #
+ # The corresponding values are sorted in an ascending order of PID.
+ labels = []
+ for tag in tags:
+ for i in range(1, values_counter[tag] + 1):
+ labels.append('%s%s' % (tag, '' if i == 1 else str(i)))
+
+ # Finally write the data into the file.
+ with open(filename, 'w') as f:
+ f.write('\t'.join(labels) + '\n')
+ for record in record_list:
+ line = cStringIO.StringIO()
+ invalid_line = False
+ for i, tag in enumerate(tags):
+ if i != 0:
+ line.write('\t')
+ values = get_values(record, tag)
+ if len(values) < values_counter[tag]:
+ invalid_line = True
+ # Fill invalid record with 0
+ values += [0] * (values_counter[tag] - len(values))
+ line.write('\t'.join(str(t) for t in values))
+ if invalid_line:
+ logging.error('Invalid record found: ' + line.getvalue())
+ line.write('\n')
+ f.write(line.getvalue())
+ print 'Wrote: ' + filename
+
+
+def median(data):
+ """Calculates the median value from |data|."""
+ data = sorted(data)
+ n = len(data)
+ if n % 2 == 1:
+ return data[n / 2]
+ else:
+ n2 = n / 2
+ return (data[n2 - 1] + data[n2]) / 2.0
+
+
+def mean(data):
+ """Calculates the mean value from |data|."""
+ return float(sum(data)) / len(data)
+
+
+def stddev(data):
+ """Calculates the standard deviation value from |value|."""
+ m = mean(data)
+ return math.sqrt(sum((x - m) ** 2 for x in data) / len(data))
+
+
+def print_summary(record_list, end_tag):
+ """Prints the summary of |record_list|."""
+ # Filter out invalid data.
+ end_times = [get_last_value(record, end_tag) for record in record_list
+ if get_last_value(record, end_tag) != 0]
+ print 'mean: ', mean(end_times)
+ print 'median:', median(end_times)
+ print 'standard deviation:', stddev(end_times)
+
+
+def do_iteration(device, interval_adjuster, event_tags_re, end_tag):
+ """Measures the boot time once."""
+ device.wait()
+ interval_adjuster.wait()
+ device.reboot()
+ print 'Rebooted the device'
+ record = {}
+ booted = False
+ while not booted:
+ device.wait()
+ # Stop the iteration if it does not finish within 120 seconds.
+ timeout = 120
+ t = WatchdogTimer(timeout)
+ p = subprocess.Popen(
+ ['adb', 'logcat', '-b', 'events', '-v', 'threadtime'],
+ stdout=subprocess.PIPE)
+ for line in readlines_unbuffered(p):
+ if t.is_timedout():
+ print '*** Timed out ***'
+ return record
+ m = event_tags_re.search(line)
+ if not m:
+ continue
+ tag = m.group('tag')
+ event_time = int(m.group('time'))
+ pid = m.group('pid')
+ record[(tag, pid)] = event_time
+ print 'Event log recorded: %s (%s) - %d ms' % (
+ tag, pid, event_time)
+ if tag == end_tag:
+ booted = True
+ t.cancel()
+ break
+ return record
+
+
+def parse_args():
+ """Parses the command line arguments."""
+ parser = argparse.ArgumentParser(
+ description=inspect.getdoc(sys.modules[__name__]),
+ formatter_class=argparse.RawDescriptionHelpFormatter)
+ parser.add_argument('--iterations', type=int, default=5,
+ help='Number of times to repeat boot measurements.')
+ parser.add_argument('--interval', type=int,
+ help=('Duration between iterations. If this is not '
+ 'set explicitly, durations are determined '
+ 'adaptively based on CPUs temperature.'))
+ parser.add_argument('-o', '--output', help='File name of output data.')
+ parser.add_argument('-v', '--verbose', action='store_true',
+ help='Show verbose output.')
+ parser.add_argument('-s', '--serial', default=os.getenv('ANDROID_SERIAL'),
+ help='Adb device serial number.')
+ parser.add_argument('-t', '--tags', help='Specify the filename from which '
+ 'event tags are read. Every line contains one event '
+ 'tag and the last event tag is used to detect that '
+ 'the device has finished booting.')
+ return parser.parse_args()
+
+
+def main():
+ args = parse_args()
+ if args.verbose:
+ logging.getLogger().setLevel(logging.INFO)
+
+ device = adb.get_device(args.serial)
+
+ if not args.output:
+ device.wait()
+ args.output = 'perf-%s-%s.tsv' % (
+ device.get_prop('ro.build.flavor'),
+ device.get_prop('ro.build.version.incremental'))
+
+ record_list = []
+ event_tags = read_event_tags(args.tags)
+ init_perf(device, args.output, record_list, event_tags)
+ interval_adjuster = IntervalAdjuster(args.interval, device)
+ event_tags_re = make_event_tags_re(event_tags)
+ end_tag = event_tags[-1]
+ for i in range(args.iterations):
+ print 'Run #%d ' % i
+ record = do_iteration(
+ device, interval_adjuster, event_tags_re, end_tag)
+ record_list.append(record)
+
+
+if __name__ == '__main__':
+ main()