Add a script to record Android boot time.

# See the License for the specific language governing permissions and

# limitations under the License.

#

import logging

import os

import re

import subprocess

        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)

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

    def usb(self):

        return self._simple_call(['usb'])

    def reboot(self):

        return self._simple_call(['reboot'])

    def root(self):

        return self._simple_call(['root'])

#!/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()