client/site_tests/platform_BootPerf/platform_BootPerf.py - mirrors/cros/chromiumos/third_party/autotest - Git at Google

 # 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 os
 import re
 import shutil
 import utils

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

 class platform_BootPerf(test.test):
     """Test to gather recorded boot time statistics."""

     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):
         """Gather boot time statistics.

         Every shutdown and boot creates files with summary statistics
         for time elapsed and disk usage.  Gather the values reported for
         shutdown, boot time and network startup time, and record them as
         perf keyvals.

         @param last_boot_was_reboot TODO(jrbarnette) This seems to serve
                 no useful purpose.

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

         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)
	# 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 os
	import re
	import shutil
	import utils

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

	class platform_BootPerf(test.test):
	"""Test to gather recorded boot time statistics."""

	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):
	"""Gather boot time statistics.

	Every shutdown and boot creates files with summary statistics
	for time elapsed and disk usage. Gather the values reported for
	shutdown, boot time and network startup time, and record them as
	perf keyvals.

	@param last_boot_was_reboot TODO(jrbarnette) This seems to serve
	no useful purpose.

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

	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)