18b73dd0b6
This is correct significant figures/units based on the precision of our
measurements, but it does not reflect our actual certainty re the output
data, since in reality, confidence is diminished by temperature, device,
hardware revision, time of day/month/year, spurious activity, data
connectivity, app install list, inherent randomness of multiprogramming,
sensor activity, user interaction, /data caches, build-by-build
differences, charging state, data fragmentation, race-driven sleeps,
cosmic radiation, factory defects, local magnetic or gravitational field
differences, changes in device momentum, or other known and unknown
causes.
Bug: N/A
Test: run perfboot.py, and output has:
mean: 10801 ms
median: 10801 ms
standard deviation: 18 ms
Change-Id: I796396acc203b29e9a14e4d6dffa58db7b8cd9fb
462 lines
16 KiB
Python
Executable file
462 lines
16 KiB
Python
Executable file
#!/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 glob
|
|
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',
|
|
'sf_stop_bootanim',
|
|
'wm_boot_animation_done',
|
|
]
|
|
|
|
|
|
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'])[0].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])[0].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.daemon = True
|
|
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'])[0].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()
|
|
debuggable = device.get_prop('ro.debuggable')
|
|
original_dropbox_max_files = None
|
|
if debuggable == '1':
|
|
# 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 check_dm_verity_settings(device):
|
|
device.wait()
|
|
for partition in ['system', 'vendor']:
|
|
verity_mode = device.get_prop('partition.%s.verified' % partition)
|
|
if verity_mode is None:
|
|
logging.warning('dm-verity is not enabled for /%s. Did you run '
|
|
'adb disable-verity? That may skew the result.',
|
|
partition)
|
|
|
|
|
|
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 filter_event_tags(tags, device):
|
|
"""Drop unknown tags not listed in device's event-log-tags file."""
|
|
device.wait()
|
|
supported_tags = set()
|
|
for l in device.shell(
|
|
['cat', '/system/etc/event-log-tags'])[0].splitlines():
|
|
tokens = l.split(' ')
|
|
if len(tokens) >= 2:
|
|
supported_tags.add(tokens[1])
|
|
filtered = []
|
|
for tag in tags:
|
|
if tag in supported_tags:
|
|
filtered.append(tag)
|
|
else:
|
|
logging.warning('Unknown tag \'%s\'. Ignoring...', tag)
|
|
return filtered
|
|
|
|
|
|
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:', int(round(mean(end_times))), 'ms'
|
|
print 'median:', int(round(median(end_times))), 'ms'
|
|
print 'standard deviation:', int(round(stddev(end_times))), 'ms'
|
|
|
|
|
|
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 unless --end-tag is '
|
|
'specified.')
|
|
parser.add_argument('--end-tag', help='An event tag on which the script '
|
|
'stops measuring the boot time.')
|
|
parser.add_argument('--apk-dir', help='Specify the directory which contains '
|
|
'APK files to be installed before measuring boot time.')
|
|
return parser.parse_args()
|
|
|
|
|
|
def install_apks(device, apk_dir):
|
|
for apk in glob.glob(os.path.join(apk_dir, '*.apk')):
|
|
print 'Installing: ' + apk
|
|
device.install(apk, replace=True)
|
|
|
|
|
|
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'))
|
|
check_dm_verity_settings(device)
|
|
|
|
if args.apk_dir:
|
|
install_apks(device, args.apk_dir)
|
|
|
|
record_list = []
|
|
event_tags = filter_event_tags(read_event_tags(args.tags), device)
|
|
end_tag = args.end_tag or event_tags[-1]
|
|
if end_tag not in event_tags:
|
|
sys.exit('%s is not a valid tag.' % end_tag)
|
|
event_tags = event_tags[0 : event_tags.index(end_tag) + 1]
|
|
init_perf(device, args.output, record_list, event_tags)
|
|
interval_adjuster = IntervalAdjuster(args.interval, device)
|
|
event_tags_re = make_event_tags_re(event_tags)
|
|
|
|
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()
|