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
