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