1 # Copyright 2017 The Chromium OS 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 pprint 7 import time 8 import re 9 10 from autotest_lib.client.common_lib import error 11 from autotest_lib.server import autotest 12 from autotest_lib.server.cros.faft.cr50_test import Cr50Test 13 14 15 class firmware_Cr50DeviceState(Cr50Test): 16 """Verify Cr50 tracks the EC and AP state correctly. 17 18 Put the device through S0, S0ix, S3, and G3. Cr50 responds to these state 19 changes by enabling/disabling uart and changing its suspend type. Verify 20 that none of these cause any interrupt storms on Cr50. Make sure that there 21 aren't any interrupt storms and that Cr50 enters regular or deep sleep a 22 reasonable amount of times. 23 """ 24 version = 1 25 26 DEEP_SLEEP_STEP_SUFFIX = ' Num Deep Sleep Steps' 27 28 # Use negative numbers to keep track of counts not in the IRQ list. 29 KEY_DEEP_SLEEP = -3 30 KEY_TIME = -2 31 KEY_RESET = -1 32 KEY_REGULAR_SLEEP = 112 33 INT_NAME = { 34 KEY_RESET : 'Reset Count', 35 KEY_DEEP_SLEEP : 'Deep Sleep Count', 36 KEY_TIME : 'Cr50 Time', 37 4 : 'HOST_CMD_DONE', 38 81 : 'GPIO0', 39 98 : 'GPIO1', 40 103 : 'I2CS WRITE', 41 KEY_REGULAR_SLEEP : 'PMU WAKEUP', 42 113 : 'AC present FED', 43 114 : 'AC present RED', 44 124 : 'RBOX_INTR_PWRB', 45 130 : 'SPS CS deassert', 46 138 : 'SPS RXFIFO LVL', 47 159 : 'SPS RXFIFO overflow', 48 160 : 'EVENT TIMER', 49 174 : 'CR50_RX_SERVO_TX', 50 177 : 'CR50_TX_SERVO_RX', 51 181 : 'AP_TX_CR50_RX', 52 184 : 'AP_RX_CR50_TX', 53 188 : 'EC_TX_CR50_RX', 54 191 : 'EC_RX_CR50_TX', 55 193 : 'USB', 56 } 57 SLEEP_KEYS = [ KEY_REGULAR_SLEEP, KEY_DEEP_SLEEP ] 58 # Cr50 won't enable any form of sleep until it has been up for 20 seconds. 59 SLEEP_DELAY = 20 60 # The time in seconds to wait in each state 61 SLEEP_TIME = 30 62 SHORT_WAIT = 5 63 CONSERVATIVE_WAIT_TIME = SLEEP_TIME + SHORT_WAIT + 10 64 # Cr50 should wake up twice per second while in regular sleep 65 SLEEP_RATE = 2 66 67 DEEP_SLEEP_MAX = 2 68 ARM = 'ARM ' 69 70 # If there are over 100,000 interrupts, it is an interrupt storm. 71 DEFAULT_COUNTS = [0, 100000] 72 # A dictionary of ok count values for each irq that shouldn't follow the 73 # DEFAULT_COUNTS range. 74 EXPECTED_IRQ_COUNT_RANGE = { 75 KEY_RESET : [0, 0], 76 KEY_DEEP_SLEEP : [0, DEEP_SLEEP_MAX], 77 KEY_TIME : [0, CONSERVATIVE_WAIT_TIME], 78 'S0ix' + DEEP_SLEEP_STEP_SUFFIX : [0, 0], 79 # Cr50 may enter deep sleep an extra time, because of how the test 80 # collects taskinfo counts. Just verify that it does enter deep sleep 81 'S3' + DEEP_SLEEP_STEP_SUFFIX : [1, 2], 82 'G3' + DEEP_SLEEP_STEP_SUFFIX : [1, 2], 83 # ARM devices don't enter deep sleep in S3 84 ARM + 'S3' + DEEP_SLEEP_STEP_SUFFIX : [0, 0], 85 ARM + 'G3' + DEEP_SLEEP_STEP_SUFFIX : [1, 2], 86 # Regular sleep is calculated based on the cr50 time 87 } 88 89 GET_TASKINFO = ['IRQ counts by type:(.*)Service calls'] 90 91 START = '' 92 INCREASE = '+' 93 DS_RESUME = 'DS' 94 95 96 def initialize(self, host, cmdline_args, full_args): 97 super(firmware_Cr50DeviceState, self).initialize(host, cmdline_args, 98 full_args) 99 # Don't bother if there is no Chrome EC or if EC hibernate doesn't work. 100 if not self.check_ec_capability(): 101 raise error.TestNAError("Nothing needs to be tested on this device") 102 103 104 def get_taskinfo_output(self): 105 """Return a dict with the irq numbers as keys and counts as values""" 106 output = self.cr50.send_command_get_output('taskinfo', 107 self.GET_TASKINFO)[0][1].strip() 108 logging.info(output) 109 return output 110 111 112 def get_irq_counts(self): 113 """Return a dict with the irq numbers as keys and counts as values""" 114 output = self.get_taskinfo_output() 115 irq_list = re.findall('\d+\s+\d+\r', output) 116 # Make sure the regular sleep irq is in the dictionary, even if cr50 117 # hasn't seen any interrupts. It's important the test sees that there's 118 # never an interrupt. 119 irq_counts = { self.KEY_REGULAR_SLEEP : 0 } 120 for irq_info in irq_list: 121 logging.debug(irq_info) 122 num, count = irq_info.split() 123 irq_counts[int(num)] = int(count) 124 irq_counts[self.KEY_RESET] = int(self.servo.get('cr50_reset_count')) 125 irq_counts[self.KEY_DEEP_SLEEP] = int(self.cr50.get_deep_sleep_count()) 126 irq_counts[self.KEY_TIME] = int(self.cr50.gettime()) 127 return irq_counts 128 129 130 def get_expected_count(self, irq_key, cr50_time): 131 """Get the expected irq increase for the given irq and state 132 133 Args: 134 irq_key: the irq int 135 cr50_time: the cr50 time in seconds 136 137 Returns: 138 A list with the expected irq count range [min, max] 139 """ 140 # CCD will prevent sleep 141 if self.ccd_enabled and (irq_key in self.SLEEP_KEYS or 142 self.DEEP_SLEEP_STEP_SUFFIX in str(irq_key)): 143 return [0, 0] 144 if irq_key == self.KEY_REGULAR_SLEEP: 145 # If cr50_time is really low, we probably woke cr50 up using 146 # taskinfo, which would be a pmu wakeup. 147 if cr50_time == 0: 148 return [0, 1] 149 150 min_count = max(cr50_time - self.SLEEP_DELAY, 0) 151 # Just checking there is not a lot of extra sleep wakeups. Add 1 to 152 # the sleep rate so cr50 can have some extra wakeups, but not too 153 # many. 154 max_count = cr50_time * (self.SLEEP_RATE + 1) 155 return [min_count, max_count] 156 return self.EXPECTED_IRQ_COUNT_RANGE.get(irq_key, self.DEFAULT_COUNTS) 157 158 159 def check_increase(self, irq_key, name, increase, expected_range): 160 """Verify the irq count is within the expected range 161 162 Args: 163 irq_key: the irq int 164 name: the irq name string 165 increase: the irq count 166 expected_range: A list with the valid irq count range [min, max] 167 168 Returns: 169 '' if increase is in the given range. If the increase isn't in the 170 range, it returns an error message. 171 """ 172 min_count, max_count = expected_range 173 if min_count > increase or max_count < increase: 174 err_msg = '%s %s: %s not in range %s' % (name, irq_key, increase, 175 expected_range) 176 return err_msg 177 return '' 178 179 180 def get_step_events(self): 181 """Use the deep sleep counts to determine the step events""" 182 ds_counts = self.get_irq_step_counts(self.KEY_DEEP_SLEEP) 183 events = [] 184 for i, count in enumerate(ds_counts): 185 if not i: 186 events.append(self.START) 187 elif count != ds_counts[i - 1]: 188 # If the deep sleep count changed, Cr50 recovered deep sleep 189 # and the irq counts are reset. 190 events.append(self.DS_RESUME) 191 else: 192 events.append(self.INCREASE) 193 return events 194 195 196 def get_irq_step_counts(self, irq_key): 197 """Get a list of the all of the step counts for the given irq""" 198 return [ irq_dict.get(irq_key, 0) for irq_dict in self.steps ] 199 200 201 def check_for_errors(self, state): 202 """Check for unexpected IRQ counts at each step. 203 204 Find the irq count errors and add them to run_errors. 205 206 Args: 207 state: The power state: S0, S0ix, S3, or G3. 208 """ 209 num_steps = len(self.steps) 210 # Get all of the deep sleep counts 211 events = self.get_step_events() 212 213 irq_list = list(self.irqs) 214 irq_list.sort() 215 216 irq_diff = ['%23s' % 'step' + ''.join(self.step_names)] 217 step_errors = [ [] for i in range(num_steps) ] 218 219 cr50_times = self.get_irq_step_counts(self.KEY_TIME) 220 cr50_diffs = [] 221 for i, cr50_time in enumerate(cr50_times): 222 if events[i] == self.INCREASE: 223 cr50_time -= cr50_times[i - 1] 224 cr50_diffs.append(cr50_time) 225 226 # Go through each irq and update its info in the progress dict 227 for irq_key in irq_list: 228 name = self.INT_NAME.get(irq_key, 'Unknown') 229 irq_progress_str = ['%19s %3s:' % (name, irq_key)] 230 231 irq_counts = self.get_irq_step_counts(irq_key) 232 for step, count in enumerate(irq_counts): 233 event = events[step] 234 235 # The deep sleep counts are not reset after deep sleep. Change 236 # the event to INCREASE. 237 if irq_key == self.KEY_DEEP_SLEEP and event == self.DS_RESUME: 238 event = self.INCREASE 239 240 if event == self.INCREASE: 241 count -= irq_counts[step - 1] 242 243 # Check that the count increase is within the expected value. 244 if event != self.START: 245 expected_range = self.get_expected_count(irq_key, 246 cr50_diffs[step]) 247 248 rv = self.check_increase(irq_key, name, count, 249 expected_range) 250 if rv: 251 logging.info('Unexpected count for %s %s', state, rv) 252 step_errors[step].append(rv) 253 254 irq_progress_str.append(' %2s %7d' % (event, count)) 255 256 irq_diff.append(''.join(irq_progress_str)) 257 258 errors = {} 259 260 ds_key = self.ARM if self.is_arm else '' 261 ds_key += state + self.DEEP_SLEEP_STEP_SUFFIX 262 expected_range = self.get_expected_count(ds_key, 0) 263 rv = self.check_increase(None, ds_key, events.count(self.DS_RESUME), 264 expected_range) 265 if rv: 266 logging.info('Unexpected count for %s %s', state, rv) 267 errors[ds_key] = rv 268 for i, step_error in enumerate(step_errors): 269 if step_error: 270 logging.error('Step %d errors:\n%s', i, 271 pprint.pformat(step_error)) 272 step = '%s step %d %s' % (state, i, self.step_names[i].strip()) 273 errors[step] = step_error 274 275 logging.info('DIFF %s IRQ Counts:\n%s', state, pprint.pformat(irq_diff)) 276 if errors: 277 logging.info('ERRORS %s IRQ Counts:\n%s', state, 278 pprint.pformat(errors)) 279 self.run_errors.update(errors) 280 281 282 def trigger_s0(self): 283 """Press the power button so the DUT will wake up.""" 284 self.servo.power_short_press() 285 286 287 def enter_state(self, state): 288 """Get the command to enter the power state""" 289 self.stage_irq_add(self.get_irq_counts(), 'start %s' % state) 290 if state == 'S0': 291 self.trigger_s0() 292 else: 293 if state == 'S0ix': 294 full_command = 'echo freeze > /sys/power/state &' 295 elif state == 'S3': 296 full_command = 'echo mem > /sys/power/state &' 297 elif state == 'G3': 298 full_command = 'poweroff' 299 self.faft_client.system.run_shell_command(full_command) 300 301 time.sleep(self.SHORT_WAIT); 302 # check state transition 303 if not self.wait_power_state(state, self.SHORT_WAIT): 304 raise error.TestFail('Platform failed to reach %s state.' % state) 305 self.stage_irq_add(self.get_irq_counts(), 'in %s' % state) 306 307 308 def stage_irq_add(self, irq_dict, name=''): 309 """Add the current irq counts to the stored dictionary of irq info""" 310 self.steps.append(irq_dict) 311 self.step_names.append('%11s' % name) 312 self.irqs.update(irq_dict.keys()) 313 314 315 def reset_irq_counts(self): 316 """Reset the test IRQ counts""" 317 self.steps = [] 318 self.step_names = [] 319 self.irqs = set() 320 321 322 def run_transition(self, state): 323 """Enter the given power state and reenter s0 324 325 Enter the power state and return to S0. Wait long enough to ensure cr50 326 will enter sleep mode, so we can verify that as well. 327 328 Args: 329 state: the power state: S0ix, S3, or G3 330 """ 331 self.reset_irq_counts() 332 333 # Enter the given state 334 self.enter_state(state) 335 336 logging.info('waiting %d seconds', self.SLEEP_TIME) 337 time.sleep(self.SLEEP_TIME) 338 339 # Return to S0 340 self.enter_state('S0') 341 342 343 def verify_state(self, state): 344 """Verify cr50 behavior while running through the power state""" 345 346 try: 347 self.run_transition(state) 348 finally: 349 # reset the system to S0 no matter what happens 350 self.trigger_s0() 351 352 # Check that the progress of the irq counts seems reasonable 353 self.check_for_errors(state) 354 355 356 def is_arm_family(self): 357 """Returns True if the DUT is an ARM device.""" 358 arch = self.host.run('arch').stdout.strip() 359 return arch in ['aarch64', 'armv7l'] 360 361 362 def run_through_power_states(self): 363 """Go through S0ix, S3, and G3. Verify there are no interrupt storms""" 364 self.run_errors = {} 365 self.ccd_str = 'ccd ' + ('enabled' if self.ccd_enabled else 'disabled') 366 logging.info('Running through states with %s', self.ccd_str) 367 368 # Initialize the Test IRQ counts 369 self.reset_irq_counts() 370 371 # Make sure the DUT is in s0 372 self.enter_state('S0') 373 374 # Check if the device supports S0ix. The exit status will be 0 if it 375 # does 1 if it doesn't. 376 result = self.host.run('check_powerd_config --suspend_to_idle', 377 ignore_status=True) 378 if not result.exit_status: 379 # Login before entering S0ix so cr50 will be able to enter regular 380 # sleep 381 client_at = autotest.Autotest(self.host) 382 client_at.run_test('login_LoginSuccess') 383 self.verify_state('S0ix') 384 385 # Enter S3 386 self.verify_state('S3') 387 388 # Enter G3 389 self.verify_state('G3') 390 if self.run_errors: 391 self.all_errors[self.ccd_str] = self.run_errors 392 393 394 def run_once(self, host): 395 """Go through S0ix, S3, and G3. Verify there are no interrupt storms""" 396 self.all_errors = {} 397 self.host = host 398 self.is_arm = self.is_arm_family() 399 supports_dts_control = self.cr50.servo_v4_supports_dts_mode() 400 401 if supports_dts_control: 402 self.cr50.ccd_disable(raise_error=True) 403 404 self.ccd_enabled = self.cr50.ccd_is_enabled() 405 self.run_through_power_states() 406 407 if supports_dts_control: 408 ccd_was_enabled = self.ccd_enabled 409 self.cr50.ccd_enable(raise_error=supports_dts_control) 410 self.ccd_enabled = self.cr50.ccd_is_enabled() 411 # If the first run had ccd disabled, and the test was able to enable 412 # ccd, run through the states again to make sure there are no issues 413 # come up when ccd is enabled. 414 if not ccd_was_enabled and self.ccd_enabled: 415 self.run_through_power_states() 416 else: 417 logging.info('Current setup only supports test with ccd %sabled.', 418 'en' if self.ccd_enabled else 'dis') 419 420 self.trigger_s0() 421 if self.all_errors: 422 raise error.TestFail('Unexpected Device State: %s' % 423 self.all_errors) 424 if not supports_dts_control: 425 raise error.TestNAError('Verified device state with %s. Please ' 426 'run with type c servo v4 to test full device state.' % 427 self.ccd_str) 428
