Home | History | Annotate | Download | only in kernel_Ktime
      1 # Copyright (c) 2014 The Chromium Authors. All rights reserved.
      2 # Use of this source code is governed by a BSD-style license that can be
      3 # found in the LICENSE file.
      4 
      5 import logging
      6 import os
      7 import re
      8 from time import sleep
      9 
     10 from autotest_lib.client.bin import test, utils
     11 from autotest_lib.client.common_lib import error
     12 
     13 class kernel_Ktime(test.test):
     14     """
     15     Test to ensure that ktime and the RTC clock are consistent.
     16 
     17     """
     18     version = 1
     19 
     20     MIN_KERNEL_VER = '3.8'
     21     MODULE_NAME = 'udelay_test'
     22     UDELAY_PATH = '/sys/kernel/debug/udelay_test'
     23     RTC_PATH = '/sys/class/rtc/rtc0/since_epoch'
     24 
     25     # How many iterations to run the test for, each iteration is usally
     26     # a second, but might be more if the skew is too large when retrieving
     27     # the RTC and ktime.
     28     TEST_DURATION = 250
     29 
     30     # Allowable drift (as a function of elapsed RTC time): 0.01%
     31     ALLOWABLE_DRIFT = 0.0001
     32 
     33     # Maximum skew between ktime readings when aligning RTC and ktime
     34     MAX_SKEW = 0.050
     35 
     36     # Diffs to average for the rolling display
     37     DIFFS_TO_AVERAGE = 30
     38 
     39     def _set_file(self, contents, filename):
     40         """
     41         Write a string to a file.
     42 
     43         @param contents: the contents to write to the file
     44         @param filename: the filename to use
     45 
     46         """
     47         logging.debug('setting %s to %s', filename, contents)
     48         with open(filename, 'w') as f:
     49             f.write(contents)
     50 
     51 
     52     def _get_file(self, filename):
     53         """
     54         Read a string from a file.
     55 
     56         @returns: the contents of the file (string)
     57 
     58         """
     59         with open(filename, 'r') as f:
     60             return f.read()
     61 
     62 
     63     def _get_rtc(self):
     64         """
     65         Get the current RTC time.
     66 
     67         @returns: the current RTC time since epoch (int)
     68 
     69         """
     70         return int(self._get_file(self.RTC_PATH))
     71 
     72 
     73     def _get_ktime(self):
     74         """
     75         Get the current ktime.
     76 
     77         @returns: the current ktime (float)
     78 
     79         """
     80         # Writing a delay of 0 will return info including the current ktime.
     81         self._set_file('0', self.UDELAY_PATH)
     82         with open(self.UDELAY_PATH, 'r') as f:
     83             for line in f:
     84                 line = line.rstrip()
     85                 logging.debug('result: %s', line)
     86                 m = re.search(r'kt=(\d+.\d+)', line)
     87                 if m:
     88                     return float(m.group(1))
     89         return 0.0
     90 
     91 
     92     def _get_times(self):
     93         """
     94         Get the rtc and estimated ktime and max potential error.
     95 
     96         Returns the RTC and a best guess of the ktime when the RTC actually
     97         ticked over to the current value.  Also returns the maximum potential
     98         error of how far they are off by.
     99 
    100         RTC ticked in the range of [ktime - max_error, ktime + max_error]
    101 
    102         @returns: list of the current rtc, estimated ktime, max error
    103 
    104         """
    105         # Times are read k1, r1, k2, r2, k3.  RTC ticks over somewhere between
    106         # r1 and r2, but since we don't know exactly when that is, the best
    107         # guess we have is between k1 and k3.
    108         rtc_older = self._get_rtc()
    109         ktime_older = self._get_ktime()
    110         rtc_old = self._get_rtc()
    111         ktime_old = self._get_ktime()
    112 
    113         # Ensure that this function returns in a reasonable number of
    114         # iterations.  If excessive skew occurs repeatedly (eg RTC is too
    115         # slow), abort.
    116         bad_skew = 0
    117         while bad_skew < 10:
    118             rtc = self._get_rtc()
    119             ktime = self._get_ktime()
    120             skew = ktime - ktime_older
    121             if skew > self.MAX_SKEW:
    122                 # Time between successive calls to ktime was too slow to
    123                 # bound the error to a reasonable value.  A few occurrences
    124                 # isn't anything to be concerned about, but if it's happening
    125                 # every second, it's worth investigating and could indicate
    126                 # that the RTC is very slow and MAX_SKEW needs to be increased.
    127                 logging.info((
    128                     'retrying excessive skew: '
    129                     'rtc [%d %d %d] ktime [%f %f %f] skew %f'),
    130                     rtc_older, rtc_old, rtc, ktime_older, ktime_old, ktime,
    131                     skew)
    132                 bad_skew += 1
    133             elif rtc != rtc_old:
    134                 if rtc_older != rtc_old or rtc != rtc_old + 1:
    135                     # This could happen if we took more than one second per
    136                     # loop and could be changed to a warning if legitimate.
    137                     raise error.TestFail('rtc progressed from %u to %u to %u' %
    138                             (rtc_older, rtc_old, rtc))
    139                 return rtc, ktime_older + skew / 2, skew / 2
    140             rtc_older = rtc_old
    141             ktime_older = ktime_old
    142             rtc_old = rtc
    143             ktime_old = ktime
    144         raise error.TestFail('could not reach skew %f after %d attempts' % (
    145                 self.MAX_SKEW, bad_skew))
    146 
    147 
    148     def run_once(self):
    149         kernel_ver = os.uname()[2]
    150         if utils.compare_versions(kernel_ver, self.MIN_KERNEL_VER) < 0:
    151             logging.info(
    152                     'skipping test: old kernel %s (min %s) missing module %s',
    153                     kernel_ver, self.MIN_KERNEL_VER, self.MODULE_NAME)
    154             return
    155 
    156         utils.load_module(self.MODULE_NAME)
    157 
    158         start_rtc, start_ktime, start_error = self._get_times()
    159         logging.info(
    160                 'start rtc %d ktime %f error %f',
    161                 start_rtc, start_ktime, start_error)
    162 
    163         recent_diffs = []
    164         max_diff = 0
    165         sum_rtc = 0
    166         sum_diff = 0
    167         sum_rtc_rtc = 0
    168         sum_rtc_diff = 0
    169         sum_diff_diff = 0
    170         for i in xrange(self.TEST_DURATION):
    171             # Sleep some amount of time to avoid busy waiting the entire time
    172             sleep((i % 10) * 0.1)
    173 
    174             current_rtc, current_ktime, current_error = self._get_times()
    175             elapsed_rtc = current_rtc - start_rtc
    176             elapsed_ktime = current_ktime - start_ktime
    177             elapsed_diff = float(elapsed_rtc) - elapsed_ktime
    178 
    179             # Allow for inaccurate ktime off ALLOWABLE_DRIFT from elapsed RTC,
    180             # and take into account start and current error in times gathering
    181             max_error = start_error + current_error
    182             drift_threshold = elapsed_rtc * self.ALLOWABLE_DRIFT + max_error
    183 
    184             # Track rolling average and maximum diff
    185             recent_diffs.append(elapsed_diff)
    186             if len(recent_diffs) > self.DIFFS_TO_AVERAGE:
    187                 recent_diffs.pop(0)
    188             rolling_diff = sum(recent_diffs) / len(recent_diffs)
    189             if abs(elapsed_diff) > abs(max_diff):
    190                 max_diff = elapsed_diff
    191 
    192             # Track linear regression
    193             sum_rtc += elapsed_rtc
    194             sum_diff += elapsed_diff
    195             sum_rtc_rtc += elapsed_rtc * elapsed_rtc
    196             sum_rtc_diff += elapsed_rtc * elapsed_diff
    197             sum_diff_diff += elapsed_diff * elapsed_diff
    198 
    199             logging.info((
    200                     'current rtc %d ktime %f error %f; elapsed rtc %d '
    201                     'ktime %f: threshold %f diff %+f rolling %+f'),
    202                     current_rtc, current_ktime, current_error, elapsed_rtc,
    203                     elapsed_ktime, drift_threshold, elapsed_diff, rolling_diff)
    204 
    205             if abs(elapsed_diff) > drift_threshold:
    206                 raise error.TestFail((
    207                         'elapsed rtc %d and ktime %f diff %f '
    208                         'is greater than threshold %f') %
    209                         (elapsed_rtc, elapsed_ktime, elapsed_diff,
    210                         drift_threshold))
    211 
    212         # Dump final statistics
    213         logging.info('max_diff %f', max_diff)
    214         mean_rtc = sum_rtc / self.TEST_DURATION
    215         mean_diff = sum_diff / self.TEST_DURATION
    216         slope = ((sum_rtc_diff - sum_rtc * mean_diff) /
    217                 (sum_rtc_rtc - sum_rtc * mean_rtc))
    218         logging.info('drift %.9f', slope)
    219 
    220         utils.unload_module(self.MODULE_NAME)
    221