# Copyright (c) 2009 The Chromium OS Authors. All rights reserved.
# Use of this source code is governed by a BSD-style license that can be
# found in the LICENSE file.

import datetime
import fnmatch
import logging
import math
import os
import re
import shutil
import StringIO
import utils

from autotest_lib.client.bin import test
from autotest_lib.client.common_lib import error

class platform_BootPerf(test.test):
    version = 2


    def __parse_shutdown_statistics(self, filename):
        """Returns a tuple containing uptime, read_sectors, and write_sectors.
        """
        with open(filename) as statfile:
            uptime = float(statfile.readline())
            read_sectors = float(statfile.readline())
            write_sectors = float(statfile.readline())

        return uptime, read_sectors, write_sectors


    def __copy_timestamp_files(self):
        tmpdir = '/tmp'
        for fname in os.listdir(tmpdir):
          if (not fnmatch.fnmatch(fname, 'uptime-*') and
                  not fnmatch.fnmatch(fname, 'disk-*')):
              continue
          shutil.copy(os.path.join(tmpdir, fname), self.resultsdir)
        try:
          shutil.copy('/tmp/firmware-boot-time', self.resultsdir)
        except:
          pass


    def __parse_uptime(self, filename):
        vals = []
        try:
            data = file(filename).read()
            vals = re.split(r' +', data.strip())
        except IOError:
            raise error.TestFail('Test is unable to read uptime file "%s"' %
                                 filename)
        return float(vals[0])


    def __parse_diskstat(self, filename):
        vals = []
        try:
            data = file(filename).read()
            vals = re.split(r' +', data.strip())
        except IOError:
            raise error.TestFail('Test is unable to read "%s"' % filename)
        return float(vals[2])


    def __parse_firmware_boot_time(self, results):
        data = None
        try:
            # If the firmware boot time is not available, the file
            # will not exist.
            data = utils.read_one_line('/tmp/firmware-boot-time')
        except IOError:
            return
        # TODO: Remove seconds_firmware_boot once the harness starts accepting
        # seconds_power_on_to_kernel
        results['seconds_firmware_boot'] = float(data)
        results['seconds_power_on_to_kernel'] = float(data)


    def __parse_vboot_times(self, results):
        # Obtain the CPU frequency
        freq_file_path = '/sys/devices/system/cpu/cpu0/cpufreq/cpuinfo_max_freq'
        try:
            hertz = int(utils.read_one_line(freq_file_path)) * 1000.0
        except IOError:
            logging.info('Test is unable to read "%s", no calculating the '
                         'vboot times.' % freq_file_path)
            return
        try:
            out = utils.system_output('crossystem')
        except error.CmdError:
            logging.info('Unable to run crossystem, not calculating the vboot '
                         'times.')
            return
        # Parse the crossystem output, we are looking for vdat_timers
        items = out.splitlines()
        for item in items:
            times_re = re.compile(r'LF=(\d+),(\d+) LK=(\d+),(\d+)')
            match = re.findall(times_re, item)
            if (match):
                times = map(lambda s: round(float(s) / hertz, 2), match[0])
                results['seconds_power_on_to_lf_start'] = times[0]
                results['seconds_power_on_to_lf_end'] = times[1]
                results['seconds_power_on_to_lk_start'] = times[2]
                results['seconds_power_on_to_lk_end'] = times[3]

    # Find the reboot/shutdown time if the last boot was a reboot.
    def __parse_syslog(self, results, last_boot_was_reboot):
        file_handle = None
        logfile = '/var/log/messages'
        try:
            file_handle = open(logfile, 'r')
        except:
            raise error.TestFail('Test is unable to read "%s"' % logfile)
        startups_found = 0
        last_shutdown_time = None
        kernel_start_time = None
        datetime_re = r'(\d{4})-(\d{2})-(\d{2})[A-Z]' + \
                      r'(\d{2}):(\d{2}):(\d{2})\.(\d{6})'
        last_shutdown_re = re.compile(
            datetime_re + r'.*(klog|tty2) main process.*killed by TERM')
        startup_re = re.compile(datetime_re + r'.*000\] Linux version \d')
        mhz_re = re.compile(r'Detected (\d+\.\d+) MHz processor.')
        mhz = 0
        for line in file_handle.readlines():
            match = startup_re.match(line)
            if match is not None:
                datetime_args = tuple([int(x) for x in match.groups()[:7]])
                kernel_start_time = datetime.datetime(*datetime_args)
                startups_found += 1
            match = last_shutdown_re.match(line)
            if match is not None:
                datetime_args = tuple([int(x) for x in match.groups()[:7]])
                last_shutdown_time = datetime.datetime(*datetime_args)
            match = mhz_re.search(line)
            if match is not None:
                mhz = float(match.group(1))
        file_handle.close()
        if (last_shutdown_time != None and last_boot_was_reboot and
            kernel_start_time != None):
            logging.info('Kernel start time: %s, last shutdown time: %s' %
                         (kernel_start_time, last_shutdown_time))
            delta = kernel_start_time - last_shutdown_time
            # There is no guarantee that we will have gotten a shutdown
            # log message/time.  It's possible to not get any kill messages
            # logged to syslog before rsyslogd itself is killed.  If
            # that occurs, this reboot time will be completely wrong.
            reboot_time = (float(delta.days) * 86400.0 +
                           float(delta.seconds) +
                           float(delta.microseconds) /
                           1000000.0)
            results['seconds_reboot_time'] = reboot_time
            results['seconds_shutdown_time'] = \
                reboot_time - results.get('seconds_firmware_boot', 0.0)
        results['reboots_in_syslog'] = startups_found
        results['mhz_primary_cpu'] = mhz


    def run_once(self, last_boot_was_reboot=False):
        # Parse key metric files and generate key/value pairs
        results = {}

        # We start by gathering the shutdown metrics from the reboot.
        try:
            prefix = '/var/log/metrics/shutdown_'
            startstats = self.__parse_shutdown_statistics(prefix + 'start')
            stopstats = self.__parse_shutdown_statistics(prefix + 'stop')
        except ValueError as e:
            raise error.TestFail('Chrome OS shutdown metrics are malformed. '
                                 'Error raised: %s' % e)
        except error.AutoservRunError:
            raise error.TestFail('Chrome OS shutdown metrics are missing.')

        results['seconds_shutdown'] = stopstats[0] - startstats[0]
        results['sectors_read_shutdown'] = stopstats[1] - startstats[1]
        results['sectors_written_shutdown'] = stopstats[2] - startstats[2]

        # Copy over the boot time results and gather those.
        self.__copy_timestamp_files()

        # Ensure we've completed the OOBE flow.
        if not os.path.exists('/home/chronos/.oobe_completed'):
            raise error.TestError('OOBE not completed.')

        uptime_files = [
            # N.B.  Keyval attribute names go into a database that
            # truncates after 30 characters.
            # ----+----1----+----2----+----3
            ('seconds_kernel_to_startup',      '/tmp/uptime-pre-startup'),
            ('seconds_kernel_to_startup_done', '/tmp/uptime-post-startup'),
            ('seconds_kernel_to_x_started',    '/tmp/uptime-x-started'),
            ('seconds_kernel_to_chrome_exec',  '/tmp/uptime-chrome-exec'),
            ('seconds_kernel_to_chrome_main',  '/tmp/uptime-chrome-main'),
            ('seconds_kernel_to_login',        '/tmp/uptime-boot-complete')
        ]

        for resultname, filename in uptime_files:
            results[resultname] = self.__parse_uptime(filename)

        # Not all 'uptime-network-*-ready' files necessarily exist;
        # probably there's only one.  We go through a list of
        # possibilities and pick the first one we find.  We're not
        # looking for 3G here, so we're not guaranteed to find any
        # file.
        network_time_files = [
            '/tmp/uptime-network-wifi-ready',
            '/tmp/uptime-network-ethernet-ready' ]

        for filename in network_time_files:
            try:
                network_time = self.__parse_uptime(filename)
                results['seconds_kernel_to_network'] = network_time
                break
            except error.TestFail:
                pass

        diskstat_files = [
            # N.B. 30 character name limit -- see above.
            # ----+----1----+----2----+----3
            ('rdbytes_kernel_to_startup',      '/tmp/disk-pre-startup'),
            ('rdbytes_kernel_to_startup_done', '/tmp/disk-post-startup'),
            ('rdbytes_kernel_to_x_started',    '/tmp/disk-x-started'),
            ('rdbytes_kernel_to_chrome_exec',  '/tmp/disk-chrome-exec'),
            ('rdbytes_kernel_to_chrome_main',  '/tmp/disk-chrome-main'),
            ('rdbytes_kernel_to_login',        '/tmp/disk-boot-complete')
        ]

        # Disk statistics are reported in units of 512 byte sectors;
        # we want the keyvals to report bytes so that downstream
        # consumers don't have to ask "How big is a sector?".
        for resultname, filename in diskstat_files:
            try:
                results[resultname] = 512 * self.__parse_diskstat(filename)
            except:
                pass

        self.__parse_firmware_boot_time(results)
        self.__parse_syslog(results, last_boot_was_reboot)
        self.__parse_vboot_times(results)

        if ('seconds_firmware_boot' in results and
            'seconds_kernel_to_login' in results):
            results['seconds_power_on_to_login'] = \
                results['seconds_firmware_boot'] + \
                results['seconds_kernel_to_login']

        self.write_perf_keyval(results)