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