blob: 5b720b26bb4d6f2713ec540db85fe52e524cc858 [file] [log] [blame]
# 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-*')):
shutil.copy(os.path.join(tmpdir, fname), self.resultsdir)
shutil.copy('/tmp/firmware-boot-time', self.resultsdir)
def __parse_uptime(self, filename):
vals = []
data = file(filename).read()
vals = re.split(r' +', data.strip())
except IOError:
raise error.TestFail('Test is unable to read uptime file "%s"' %
return float(vals[0])
def __parse_diskstat(self, filename):
vals = []
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
# If the firmware boot time is not available, the file
# will not exist.
data = utils.read_one_line('/tmp/firmware-boot-time')
except IOError:
# 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'
hertz = int(utils.read_one_line(freq_file_path)) * 1000.0
except IOError:'Test is unable to read "%s", no calculating the '
'vboot times.' % freq_file_path)
out = utils.system_output('crossystem')
except error.CmdError:'Unable to run crossystem, not calculating the vboot '
# 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'
file_handle = open(logfile, 'r')
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]' + \
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 =
if match is not None:
mhz = float(
if (last_shutdown_time != None and last_boot_was_reboot and
kernel_start_time != None):'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) /
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.
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.
# 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-ethernet-ready' ]
for filename in network_time_files:
network_time = self.__parse_uptime(filename)
results['seconds_kernel_to_network'] = network_time
except error.TestFail:
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:
results[resultname] = 512 * self.__parse_diskstat(filename)
self.__parse_syslog(results, last_boot_was_reboot)
if ('seconds_firmware_boot' in results and
'seconds_kernel_to_login' in results):
results['seconds_power_on_to_login'] = \
results['seconds_firmware_boot'] + \