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