225 lines
8.0 KiB
Python
225 lines
8.0 KiB
Python
# Copyright (c) 2014 The Chromium 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 logging
|
|
import os
|
|
import re
|
|
from time import sleep
|
|
|
|
from autotest_lib.client.bin import test, utils
|
|
from autotest_lib.client.common_lib import error
|
|
|
|
class kernel_Ktime(test.test):
|
|
"""
|
|
Test to ensure that ktime and the RTC clock are consistent.
|
|
|
|
"""
|
|
version = 1
|
|
|
|
MIN_KERNEL_VER = '3.8'
|
|
KERNEL_VER = '3.18'
|
|
MODULE_NAME = 'udelay_test'
|
|
MODULE_NAME_NEW = 'test_udelay'
|
|
UDELAY_PATH = '/sys/kernel/debug/udelay_test'
|
|
RTC_PATH = '/sys/class/rtc/rtc0/since_epoch'
|
|
|
|
# How many iterations to run the test for, each iteration is usally
|
|
# a second, but might be more if the skew is too large when retrieving
|
|
# the RTC and ktime.
|
|
TEST_DURATION = 250
|
|
|
|
# Allowable drift (as a function of elapsed RTC time): 0.01%
|
|
ALLOWABLE_DRIFT = 0.0001
|
|
|
|
# Maximum skew between ktime readings when aligning RTC and ktime
|
|
MAX_SKEW = 0.050
|
|
|
|
# Diffs to average for the rolling display
|
|
DIFFS_TO_AVERAGE = 30
|
|
|
|
def _set_file(self, contents, filename):
|
|
"""
|
|
Write a string to a file.
|
|
|
|
@param contents: the contents to write to the file
|
|
@param filename: the filename to use
|
|
|
|
"""
|
|
logging.debug('setting %s to %s', filename, contents)
|
|
with open(filename, 'w') as f:
|
|
f.write(contents)
|
|
|
|
|
|
def _get_file(self, filename):
|
|
"""
|
|
Read a string from a file.
|
|
|
|
@returns: the contents of the file (string)
|
|
|
|
"""
|
|
with open(filename, 'r') as f:
|
|
return f.read()
|
|
|
|
|
|
def _get_rtc(self):
|
|
"""
|
|
Get the current RTC time.
|
|
|
|
@returns: the current RTC time since epoch (int)
|
|
|
|
"""
|
|
return int(self._get_file(self.RTC_PATH))
|
|
|
|
|
|
def _get_ktime(self):
|
|
"""
|
|
Get the current ktime.
|
|
|
|
@returns: the current ktime (float)
|
|
|
|
"""
|
|
# Writing a delay of 0 will return info including the current ktime.
|
|
self._set_file('0', self.UDELAY_PATH)
|
|
with open(self.UDELAY_PATH, 'r') as f:
|
|
for line in f:
|
|
line = line.rstrip()
|
|
logging.debug('result: %s', line)
|
|
m = re.search(r'kt=(\d+.\d+)', line)
|
|
if m:
|
|
return float(m.group(1))
|
|
return 0.0
|
|
|
|
|
|
def _get_times(self):
|
|
"""
|
|
Get the rtc and estimated ktime and max potential error.
|
|
|
|
Returns the RTC and a best guess of the ktime when the RTC actually
|
|
ticked over to the current value. Also returns the maximum potential
|
|
error of how far they are off by.
|
|
|
|
RTC ticked in the range of [ktime - max_error, ktime + max_error]
|
|
|
|
@returns: list of the current rtc, estimated ktime, max error
|
|
|
|
"""
|
|
# Times are read k1, r1, k2, r2, k3. RTC ticks over somewhere between
|
|
# r1 and r2, but since we don't know exactly when that is, the best
|
|
# guess we have is between k1 and k3.
|
|
rtc_older = self._get_rtc()
|
|
ktime_older = self._get_ktime()
|
|
rtc_old = self._get_rtc()
|
|
ktime_old = self._get_ktime()
|
|
|
|
# Ensure that this function returns in a reasonable number of
|
|
# iterations. If excessive skew occurs repeatedly (eg RTC is too
|
|
# slow), abort.
|
|
bad_skew = 0
|
|
while bad_skew < 10:
|
|
rtc = self._get_rtc()
|
|
ktime = self._get_ktime()
|
|
skew = ktime - ktime_older
|
|
if skew > self.MAX_SKEW:
|
|
# Time between successive calls to ktime was too slow to
|
|
# bound the error to a reasonable value. A few occurrences
|
|
# isn't anything to be concerned about, but if it's happening
|
|
# every second, it's worth investigating and could indicate
|
|
# that the RTC is very slow and MAX_SKEW needs to be increased.
|
|
logging.info((
|
|
'retrying excessive skew: '
|
|
'rtc [%d %d %d] ktime [%f %f %f] skew %f'),
|
|
rtc_older, rtc_old, rtc, ktime_older, ktime_old, ktime,
|
|
skew)
|
|
bad_skew += 1
|
|
elif rtc != rtc_old:
|
|
if rtc_older != rtc_old or rtc != rtc_old + 1:
|
|
# This could happen if we took more than one second per
|
|
# loop and could be changed to a warning if legitimate.
|
|
raise error.TestFail('rtc progressed from %u to %u to %u' %
|
|
(rtc_older, rtc_old, rtc))
|
|
return rtc, ktime_older + skew / 2, skew / 2
|
|
rtc_older = rtc_old
|
|
ktime_older = ktime_old
|
|
rtc_old = rtc
|
|
ktime_old = ktime
|
|
raise error.TestFail('could not reach skew %f after %d attempts' % (
|
|
self.MAX_SKEW, bad_skew))
|
|
|
|
|
|
def run_once(self):
|
|
kernel_ver = os.uname()[2]
|
|
if utils.compare_versions(kernel_ver, self.MIN_KERNEL_VER) < 0:
|
|
logging.info(
|
|
'skipping test: old kernel %s (min %s) missing module %s',
|
|
kernel_ver, self.MIN_KERNEL_VER, self.MODULE_NAME)
|
|
return
|
|
elif utils.compare_versions(kernel_ver, self.KERNEL_VER) < 0:
|
|
utils.load_module(self.MODULE_NAME)
|
|
elif utils.compare_versions(kernel_ver, self.KERNEL_VER) > 0:
|
|
utils.load_module(self.MODULE_NAME_NEW)
|
|
|
|
start_rtc, start_ktime, start_error = self._get_times()
|
|
logging.info(
|
|
'start rtc %d ktime %f error %f',
|
|
start_rtc, start_ktime, start_error)
|
|
|
|
recent_diffs = []
|
|
max_diff = 0
|
|
sum_rtc = 0
|
|
sum_diff = 0
|
|
sum_rtc_rtc = 0
|
|
sum_rtc_diff = 0
|
|
sum_diff_diff = 0
|
|
for i in xrange(self.TEST_DURATION):
|
|
# Sleep some amount of time to avoid busy waiting the entire time
|
|
sleep((i % 10) * 0.1)
|
|
|
|
current_rtc, current_ktime, current_error = self._get_times()
|
|
elapsed_rtc = current_rtc - start_rtc
|
|
elapsed_ktime = current_ktime - start_ktime
|
|
elapsed_diff = float(elapsed_rtc) - elapsed_ktime
|
|
|
|
# Allow for inaccurate ktime off ALLOWABLE_DRIFT from elapsed RTC,
|
|
# and take into account start and current error in times gathering
|
|
max_error = start_error + current_error
|
|
drift_threshold = elapsed_rtc * self.ALLOWABLE_DRIFT + max_error
|
|
|
|
# Track rolling average and maximum diff
|
|
recent_diffs.append(elapsed_diff)
|
|
if len(recent_diffs) > self.DIFFS_TO_AVERAGE:
|
|
recent_diffs.pop(0)
|
|
rolling_diff = sum(recent_diffs) / len(recent_diffs)
|
|
if abs(elapsed_diff) > abs(max_diff):
|
|
max_diff = elapsed_diff
|
|
|
|
# Track linear regression
|
|
sum_rtc += elapsed_rtc
|
|
sum_diff += elapsed_diff
|
|
sum_rtc_rtc += elapsed_rtc * elapsed_rtc
|
|
sum_rtc_diff += elapsed_rtc * elapsed_diff
|
|
sum_diff_diff += elapsed_diff * elapsed_diff
|
|
|
|
logging.info((
|
|
'current rtc %d ktime %f error %f; elapsed rtc %d '
|
|
'ktime %f: threshold %f diff %+f rolling %+f'),
|
|
current_rtc, current_ktime, current_error, elapsed_rtc,
|
|
elapsed_ktime, drift_threshold, elapsed_diff, rolling_diff)
|
|
|
|
if abs(elapsed_diff) > drift_threshold:
|
|
raise error.TestFail((
|
|
'elapsed rtc %d and ktime %f diff %f '
|
|
'is greater than threshold %f') %
|
|
(elapsed_rtc, elapsed_ktime, elapsed_diff,
|
|
drift_threshold))
|
|
|
|
# Dump final statistics
|
|
logging.info('max_diff %f', max_diff)
|
|
mean_rtc = sum_rtc / self.TEST_DURATION
|
|
mean_diff = sum_diff / self.TEST_DURATION
|
|
slope = ((sum_rtc_diff - sum_rtc * mean_diff) /
|
|
(sum_rtc_rtc - sum_rtc * mean_rtc))
|
|
logging.info('drift %.9f', slope)
|
|
|
|
utils.unload_module(self.MODULE_NAME)
|