1# Copyright 2016 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 5import datetime 6import logging 7import time 8 9from autotest_lib.client.common_lib import error 10from autotest_lib.server import autotest 11from autotest_lib.server import test 12 13_POWERD_LOG_PATH = '/var/log/power_manager/powerd.LATEST' 14_RESUME_END_LOG = '\"daemon.* Chrome is using normal display mode$\"' 15_RESUME_START_LOG = '\"suspender.*Finishing request [0-9]+ successfully after [0-9]+s\"' 16_SERVO_USB_NUM = 2 17_SHORT_WAIT_ = 5 18_SUSPEND_END_LOG = '\"suspender.* Starting suspend$\"' 19_SUSPEND_START_LOG = '\"suspender.* Starting request [0-9]+$\"' 20_SUSPEND_TIME = 15 21_TIME_TO_RESUME_BAR = 3 22_TIME_TO_SUSPEND_BAR = 3 23_SLEEP_AFTER_RESUME = 60 24_SLEEP_AFTER_REBOOT = 30 25 26class platform_SuspendResumeTiming(test.test): 27 """Checks suspend and resume happen in reasonable timelines.""" 28 version = 1 29 30 31 def cleanup(self): 32 """ Disconnect servo hub.""" 33 self.host.servo.set('dut_hub1_rst1', 'on') 34 self.host.servo.set('usb_mux_sel3', 'servo_sees_usbkey') 35 36 37 def get_suspender_log_stamp(self, pwrd_log): 38 """ Reads powerd log and takes suspend and resume logs timestamps. 39 40 @param pwrd_log: log string to search for. 41 42 @raises TestError: if suspender log is met more than once. 43 44 @returns log timestamp as datetime. 45 """ 46 out_log = self.host.run('tac %s | grep -E %s' 47 % (_POWERD_LOG_PATH, pwrd_log), 48 ignore_status=True).stdout.strip() 49 log_count = len(out_log.split('\n')) 50 if log_count != 1: 51 raise error.TestError('Log \"%s\" is found %d times!' 52 % (pwrd_log, log_count)) 53 return datetime.datetime.strptime(out_log[1:12], "%m%d/%H%M%S") 54 55 56 def get_display_mode_timestamp(self): 57 """ Takes the first _RESUME_END_LOG line after _RESUME_START_LOG line 58 and returns its timestamp. 59 60 @returns log timestamp as datetime. 61 """ 62 63 cmd = ('sed -nr \'/%s/,$p\' %s | grep -E %s | head -n 1' 64 % (_RESUME_START_LOG.replace("\"",""), 65 _POWERD_LOG_PATH, _RESUME_END_LOG)) 66 out_log = self.host.run(cmd, ignore_status=True).stdout.strip() 67 return datetime.datetime.strptime(out_log[1:12], "%m%d/%H%M%S") 68 69 70 def get_suspend_resume_time(self): 71 """ Reads powerd log and takes suspend and resume timestamps. 72 73 @returns times took to suspend and resume as a tuple. 74 75 @raises error.TestError: if timestamps are not sequential. 76 """ 77 78 suspend_start = self.get_suspender_log_stamp(_SUSPEND_START_LOG) 79 suspend_end = self.get_suspender_log_stamp(_SUSPEND_END_LOG) 80 resume_start = self.get_suspender_log_stamp(_RESUME_START_LOG) 81 resume_end = self.get_display_mode_timestamp() 82 83 84 logging.info([suspend_start, suspend_end, 85 resume_start, resume_end]) 86 87 if not all([resume_end >= resume_start, 88 resume_start > suspend_end, 89 suspend_end >= suspend_start]): 90 raise error.TestError('Log timestamps are not sequental!') 91 92 time_to_susp = (suspend_end - suspend_start).total_seconds() 93 time_to_res = (resume_end - resume_start).total_seconds() 94 95 return (time_to_susp, time_to_res) 96 97 98 def get_lsusb_lines(self): 99 """ Executes lsusb and returns list of the output lines.""" 100 output =self.host.run('lsusb', ignore_status=True).stdout 101 return output.strip().split('\n') 102 103 104 def run_once(self, host, plug_usb=False): 105 """ Running the suspend-resume timing test. 106 107 @param host: device under test host. 108 @param plug_usb: whether to plug extetrnal USB through servo. 109 110 @raises TestFail: if time to suspend to resume exceeds the bar 111 and if no peripherals are connected to servo. 112 """ 113 self.host = host 114 self.host.servo.set('dut_hub1_rst1', 'on') 115 116 # Reboot to create new powerd.Latest log file. 117 self.host.reboot() 118 time.sleep(_SLEEP_AFTER_REBOOT) 119 120 # Test user login. 121 autotest_client = autotest.Autotest(self.host) 122 autotest_client.run_test("desktopui_SimpleLogin", 123 exit_without_logout=True) 124 125 # Plug USB hub with peripherals. 126 if plug_usb: 127 lsusb_unplugged_len = len(self.get_lsusb_lines()) 128 self.host.servo.switch_usbkey('dut') 129 self.host.servo.set('usb_mux_sel3', 'dut_sees_usbkey') 130 self.host.servo.set('dut_hub1_rst1', 'off') 131 time.sleep(_SHORT_WAIT_) 132 lsusb_plugged_len = len(self.get_lsusb_lines()) 133 if lsusb_plugged_len - lsusb_unplugged_len < _SERVO_USB_NUM + 1: 134 raise error.TestFail('No peripherals are connected to servo!') 135 136 try: 137 self.host.suspend(suspend_time=_SUSPEND_TIME) 138 except error.AutoservSuspendError: 139 pass 140 time.sleep(_SLEEP_AFTER_RESUME) 141 self.host.run('sync') 142 143 # powerd log output for debug log 144 self.host.run('cat %s' % _POWERD_LOG_PATH, 145 ignore_status=True).stdout.strip() 146 147 errors = [] 148 time_to_suspend, time_to_resume = self.get_suspend_resume_time() 149 if time_to_suspend > _TIME_TO_SUSPEND_BAR: 150 errors.append('Suspend time is too long: %d' % time_to_suspend) 151 if time_to_resume > _TIME_TO_RESUME_BAR: 152 errors.append('Resume time is too long: %d' % time_to_resume) 153 if errors: 154 raise error.TestFail('; '.join(set(errors))) 155 156 157