From ab3798399dfe970a12a25f79c4392602b6d7515b Mon Sep 17 00:00:00 2001
From: Yasuhiro Matsuda <mazda@google.com>
Date: Fri, 3 Jul 2015 02:08:55 +0900
Subject: [PATCH] Add a script to record Android boot time.

perfboot.py 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.
This script also works around the issue of dropbox slowing down
boot time on userdebug build (http://b/20890386) by limiting
the number of files to be created by dropbox.
The result is output in a tab-separated value format.

BUG: 22207911
Change-Id: I0ddbac5d1c941efda87bc6db6388d8194d4bb3dd
---
 adb/device.py    |   7 +
 init/perfboot.py | 411 +++++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 418 insertions(+)
 create mode 100755 init/perfboot.py

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<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()