• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
1# Copyright (c) 2012 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 collections, logging, os, re, subprocess, time
6
7from autotest_lib.client.bin import utils
8from autotest_lib.client.common_lib import error
9from autotest_lib.client.cros import cros_logging
10from autotest_lib.client.cros.power import power_status
11from autotest_lib.client.cros.power import power_utils
12from autotest_lib.client.cros.power import sys_power
13#pylint: disable=W0611
14from autotest_lib.client.cros import flimflam_test_path
15import flimflam
16
17class Suspender(object):
18    """Class for suspend/resume measurements.
19
20    Public attributes:
21        disconnect_3G_time: Amount of seconds it took to disable 3G.
22        successes[]: List of timing measurement dicts from successful suspends.
23        failures[]: List of SuspendFailure exceptions from failed suspends.
24        device_times[]: List of individual device suspend/resume time dicts.
25
26    Public methods:
27        suspend: Do a suspend/resume cycle. Return timing measurement dict.
28
29    Private attributes:
30        _logs: Array of /var/log/messages lines since start of suspend cycle.
31        _log_file: Open file descriptor at the end of /var/log/messages.
32        _logdir: Directory to store firmware logs in case of errors.
33        _suspend: Set to the sys_power suspend function to use.
34        _throw: Set to have SuspendFailure exceptions raised to the caller.
35        _reset_pm_print_times: Set to deactivate pm_print_times after the test.
36        _restart_tlsdated: Set to restart tlsdated after the test.
37
38    Private methods:
39        __init__: Shuts off tlsdated for duration of test, disables 3G
40        __del__: Restore tlsdated (must run eventually, but GC delay no problem)
41        _set_pm_print_times: Enable/disable kernel device suspend timing output.
42        _check_failure_log: Check /sys/.../suspend_stats for new failures.
43        _ts: Returns a timestamp from /run/power_manager/last_resume_timings
44        _hwclock_ts: Read RTC timestamp left on resume in hwclock-on-resume
45        _device_resume_time: Read seconds overall device resume took from logs.
46        _individual_device_times: Reads individual device suspend/resume times.
47        _identify_driver: Return the driver name of a device (or "unknown").
48    """
49
50    # board-specific "time to suspend" values determined empirically
51    # TODO: migrate to separate file with http://crosbug.com/38148
52    _DEFAULT_SUSPEND_DELAY = 5
53    _SUSPEND_DELAY = {
54        # TODO: Reevaluate this when http://crosbug.com/38460 is fixed
55        'daisy': 6,
56        'daisy_spring': 6,
57        'peach_pit': 6,
58
59        # TODO: Reevaluate these when http://crosbug.com/38225 is fixed
60        'x86-mario': 6,
61        'x86-alex': 5,
62
63        # Lumpy and Stumpy need high values, because it seems to mitigate their
64        # RTC interrupt problem. See http://crosbug.com/36004
65        'lumpy': 5,
66        'stumpy': 5,
67
68        # RTS5209 card reader has a really bad staging driver, can take ~1 sec
69        'butterfly': 4,
70
71        # Hard disk sync and overall just slow
72        'parrot': 8,
73        'kiev': 9,
74    }
75
76    # alarm/not_before value guaranteed to raise SpuriousWakeup in _hwclock_ts
77    _ALARM_FORCE_EARLY_WAKEUP = 2147483647
78
79    # File written by send_metrics_on_resume containing timing information about
80    # the last resume.
81    _TIMINGS_FILE = '/run/power_manager/root/last_resume_timings'
82
83    # Latest powerd log files
84    _POWERD_LOG_LATEST_PATH = '/var/log/power_manager/powerd.LATEST'
85    _POWERD_LOG_PREVIOUS_PATH = '/var/log/power_manager/powerd.PREVIOUS'
86
87    # Line to look for suspend abort due to override.
88    _ABORT_DUE_TO_OVERRIDE_LINE = 'Aborting suspend attempt for lockfile'
89
90    # Regexp to extract TS from powerd log line.
91    _POWERD_TS_RE = '\[(\d{4}/\d{6}\.\d{6}):.*\]'
92
93    # Amount of lines to dump from the eventlog on a SpuriousWakeup. Should be
94    # enough to include ACPI Wake Reason... 10 should be far on the safe side.
95    _RELEVANT_EVENTLOG_LINES = 10
96
97    # Sanity check value to catch overlong resume times (from missed RTC wakes)
98    _MAX_RESUME_TIME = 10
99
100    # File written by powerd_suspend containing the hwclock time at resume.
101    HWCLOCK_FILE = '/run/power_manager/root/hwclock-on-resume'
102
103    # File read by powerd to decide on the state to suspend (mem or freeze).
104    _SUSPEND_STATE_PREF_FILE = 'suspend_to_idle'
105
106    # (b/79442787) Ignore these uarch for s0ix residency counter checking
107    _IGNORE_S0IX_RESIDENCY_CHECK = ['Skylake']
108
109    def __init__(self, logdir, method=sys_power.do_suspend,
110                 throw=False, device_times=False, suspend_state=''):
111        """
112        Prepare environment for suspending.
113        @param suspend_state: Suspend state to enter into. It can be
114                              'mem' or 'freeze' or an empty string. If
115                              the suspend state is an empty string,
116                              system suspends to the default pref.
117        """
118        self.disconnect_3G_time = 0
119        self.successes = []
120        self.failures = []
121        self._logdir = logdir
122        self._suspend = method
123        self._throw = throw
124        self._reset_pm_print_times = False
125        self._restart_tlsdated = False
126        self._log_file = None
127        self._powerd_cycle_start_ts = None
128        self._suspend_state = suspend_state
129        if device_times:
130            self.device_times = []
131
132        # stop tlsdated, make sure we/hwclock have /dev/rtc for ourselves
133        if utils.system_output('initctl status tlsdated').find('start') != -1:
134            utils.system('initctl stop tlsdated')
135            self._restart_tlsdated = True
136            # give process's file descriptors time to asynchronously tear down
137            time.sleep(0.1)
138
139        # prime powerd_suspend RTC timestamp saving and make sure hwclock works
140        utils.open_write_close(self.HWCLOCK_FILE, '')
141        hwclock_output = utils.system_output('hwclock -r --verbose --utc',
142                                             ignore_status=True)
143        if not re.search('Using.*rtc interface to.*clock', hwclock_output):
144            raise error.TestError('hwclock cannot find rtc: ' + hwclock_output)
145
146        # activate device suspend timing debug output
147        if hasattr(self, 'device_times'):
148            if not int(utils.read_one_line('/sys/power/pm_print_times')):
149                self._set_pm_print_times(True)
150                self._reset_pm_print_times = True
151
152        # Shut down 3G to remove its variability from suspend time measurements
153        flim = flimflam.FlimFlam()
154        service = flim.FindCellularService(0)
155        if service:
156            logging.info('Found 3G interface, disconnecting.')
157            start_time = time.time()
158            (success, status) = flim.DisconnectService(
159                    service=service, wait_timeout=60)
160            if success:
161                logging.info('3G disconnected successfully.')
162                self.disconnect_3G_time = time.time() - start_time
163            else:
164                logging.error('Could not disconnect: %s.', status)
165                self.disconnect_3G_time = -1
166
167        self._configure_suspend_state()
168
169
170    def _configure_suspend_state(self):
171        """Configure the suspend state as requested."""
172        if self._suspend_state:
173            available_suspend_states = utils.read_one_line('/sys/power/state')
174            if self._suspend_state not in available_suspend_states:
175                raise error.TestNAError('Invalid suspend state: ' +
176                                        self._suspend_state)
177            # Check the current state. If it is same as the one requested,
178            # we don't want to call PowerPrefChanger(restarts powerd).
179            if self._suspend_state == power_utils.get_sleep_state():
180                return
181            should_freeze = '1' if self._suspend_state == 'freeze' else '0'
182            new_prefs = {self._SUSPEND_STATE_PREF_FILE: should_freeze}
183            self._power_pref_changer = power_utils.PowerPrefChanger(new_prefs)
184
185
186    def _set_pm_print_times(self, on):
187        """Enable/disable extra suspend timing output from powerd to syslog."""
188        if utils.system('echo %s > /sys/power/pm_print_times' % int(bool(on)),
189                ignore_status=True):
190            logging.warning('Failed to set pm_print_times to %s', bool(on))
191            del self.device_times
192            self._reset_pm_print_times = False
193        else:
194            logging.info('Device resume times set to %s', bool(on))
195
196
197    def _get_board(self):
198        """Remove _freon from get_board if found."""
199        return (utils.get_board().replace("_freon", ""))
200
201
202    def _retrive_last_matching_line_ts(self, filename, pattern):
203        """
204        Returns timestamp of last matching line or None
205        """
206        with open(filename) as f:
207            lines = f.readlines()
208            for line in reversed(lines):
209                if re.search(pattern, line):
210                    matches = re.search(self._POWERD_TS_RE, line)
211                    if matches:
212                        return matches.group(1)
213        return None
214
215
216    def _aborted_due_to_locking(self):
217        """
218        Returns true if we found evidences in the powerd log that the suspend
219        was aborted due to power_management override lock.
220        """
221        latest_ts = self._retrive_last_matching_line_ts(
222            self._POWERD_LOG_LATEST_PATH, self._ABORT_DUE_TO_OVERRIDE_LINE)
223        if latest_ts is None:
224            latest_ts = self._retrive_last_matching_line_ts(
225                self._POWERD_LOG_PREVIOUS_PATH, self._ABORT_DUE_TO_OVERRIDE_LINE)
226
227        if latest_ts is None:
228            return False
229
230        if latest_ts > self._powerd_cycle_start_ts:
231            return True
232
233        return False
234
235
236    def _reset_logs(self):
237        """Throw away cached log lines and reset log pointer to current end."""
238        if self._log_file:
239            self._log_file.close()
240        self._log_file = open('/var/log/messages')
241        self._log_file.seek(0, os.SEEK_END)
242        self._logs = []
243
244        self._powerd_cycle_start_ts = (
245            self._retrive_last_matching_line_ts(self._POWERD_LOG_LATEST_PATH,
246                                                self._POWERD_TS_RE))
247
248
249    def _check_resume_finished(self, retries=11):
250        """
251        Read all lines logged since last reset into log cache. Block until last
252        powerd_suspend resume message was read. Returns true if succeeded or
253        false if took too long
254        """
255        finished_regex = re.compile(r'powerd_suspend\[\d+\]: Resume finished')
256        for retry in xrange(retries + 1):
257            lines = self._log_file.readlines()
258            if lines:
259                if self._logs and self._logs[-1][-1] != '\n':
260                    # Reassemble line that was cut in the middle
261                    self._logs[-1] += lines.pop(0)
262                self._logs += lines
263            for line in reversed(self._logs):
264                if (finished_regex.search(line)):
265                    return True
266            time.sleep(0.005 * 2**retry)
267
268        return False
269
270
271    def _ts(self, name, retries=11):
272        """Searches logs for last timestamp with a given suspend message."""
273        # Occasionally need to retry due to races from process wakeup order
274        for retry in xrange(retries + 1):
275            try:
276                f = open(self._TIMINGS_FILE)
277                for line in f:
278                    words = line.split('=')
279                    if name == words[0]:
280                        try:
281                            timestamp = float(words[1])
282                        except ValueError:
283                            logging.warning('Invalid timestamp: %s', line)
284                            timestamp = 0
285                        return timestamp
286            except IOError:
287                pass
288            time.sleep(0.005 * 2**retry)
289
290        raise error.TestError('Could not find %s entry.' % name)
291
292
293    def _hwclock_ts(self, not_before):
294        """Read the RTC resume timestamp saved by powerd_suspend."""
295        early_wakeup = False
296        if os.path.exists(self.HWCLOCK_FILE):
297            # TODO(crbug.com/733773): Still fragile see bug.
298            match = re.search(r'(.+)(\.\d+)[+-]\d+:?\d+$',
299                              utils.read_file(self.HWCLOCK_FILE), re.DOTALL)
300            if match:
301                timeval = time.strptime(match.group(1), "%Y-%m-%d %H:%M:%S")
302                seconds = time.mktime(timeval)
303                seconds += float(match.group(2))
304                logging.debug('RTC resume timestamp read: %f', seconds)
305                if not_before is None or seconds >= not_before:
306                    return seconds
307                early_wakeup = True
308        if early_wakeup:
309            logging.debug('Early wakeup, dumping eventlog if it exists:\n')
310            elog = utils.system_output('mosys eventlog list | tail -n %d' %
311                    self._RELEVANT_EVENTLOG_LINES, ignore_status=True)
312            wake_elog = (['unknown'] + re.findall(r'Wake Source.*', elog))[-1]
313            for line in reversed(self._logs):
314                match = re.search(r'PM1_STS: WAK.*', line)
315                if match:
316                    wake_syslog = match.group(0)
317                    break
318            else:
319                wake_syslog = 'unknown'
320            for b, e, s in sys_power.SpuriousWakeupError.S3_ALLOWLIST:
321                if (re.search(b, utils.get_board()) and
322                        re.search(e, wake_elog) and re.search(s, wake_syslog)):
323                    logging.warning('Allowlisted spurious wake in S3: %s | %s',
324                                    wake_elog, wake_syslog)
325                    return None
326            raise sys_power.SpuriousWakeupError('Spurious wake in S3: %s | %s'
327                    % (wake_elog, wake_syslog))
328        raise error.TestError('Broken RTC timestamp: ' +
329                              utils.read_file(self.HWCLOCK_FILE))
330
331
332    def _firmware_resume_time(self):
333        """Calculate seconds for firmware resume from logged TSC. (x86 only)"""
334        if utils.get_arch() not in ['i686', 'x86_64']:
335            # TODO: support this on ARM somehow
336            return 0
337        regex_freeze = re.compile(r'PM: resume from suspend-to-idle')
338        regex_tsc = re.compile(r'TSC at resume: (\d+)$')
339        freq = 1000 * int(utils.read_one_line(
340                '/sys/devices/system/cpu/cpu0/cpufreq/cpuinfo_max_freq'))
341        for line in reversed(self._logs):
342            match_freeze = regex_freeze.search(line)
343            if match_freeze:
344                logging.info('fw resume time zero due to suspend-to-idle\n')
345                return 0
346            match_tsc = regex_tsc.search(line)
347            if match_tsc:
348                return float(match_tsc.group(1)) / freq
349
350        raise error.TestError('Failed to find TSC resume value in syslog.')
351
352
353    def _device_resume_time(self):
354        """Read amount of seconds for overall device resume from syslog."""
355        regex = re.compile(r'PM: resume of devices complete after ([0-9.]+)')
356        for line in reversed(self._logs):
357            match = regex.search(line)
358            if match:
359                return float(match.group(1)) / 1000
360
361        raise error.TestError('Failed to find device resume time in syslog.')
362
363
364    def _get_phase_times(self):
365        phase_times = []
366        regex = re.compile(r'PM: (\w+ )?(resume|suspend) of devices complete')
367        for line in self._logs:
368          match = regex.search(line)
369          if match:
370            ts = cros_logging.extract_kernel_timestamp(line)
371            phase = match.group(1)
372            if not phase:
373              phase = 'REG'
374            phase_times.append((phase.upper(), ts))
375        return sorted(phase_times, key = lambda entry: entry[1])
376
377
378    def _get_phase(self, ts, phase_table, dev):
379      for entry in phase_table:
380        #checking if timestamp was before that phase's cutoff
381        if ts < entry[1]:
382          return entry[0]
383      raise error.TestError('Device %s has a timestamp after all devices %s',
384                            dev, 'had already resumed')
385
386
387    def _individual_device_times(self, start_resume):
388        """Return dict of individual device suspend and resume times."""
389        self.device_times.append(dict())
390        dev_details = collections.defaultdict(dict)
391        regex = re.compile(r'call ([^ ]+)\+ returned 0 after ([0-9]+) usecs')
392        phase_table = self._get_phase_times()
393        for line in self._logs:
394          match = regex.search(line)
395          if match:
396            device = match.group(1).replace(':', '-')
397            key = 'seconds_dev_' + device
398            secs = float(match.group(2)) / 1e6
399            ts = cros_logging.extract_kernel_timestamp(line)
400            if ts > start_resume:
401              key += '_resume'
402            else:
403              key += '_suspend'
404            #looking if we're in a special phase
405            phase = self._get_phase(ts, phase_table, device)
406            dev = dev_details[key]
407            if phase in dev:
408              logging.warning('Duplicate %s entry for device %s, +%f', phase,
409                              device, secs)
410              dev[phase] += secs
411            else:
412              dev[phase] = secs
413
414        for dev_key, dev in dev_details.iteritems():
415          total_secs = sum(dev.values())
416          self.device_times[-1][dev_key] = total_secs
417          report = '%s: %f TOT' % (dev_key, total_secs)
418          for phase in dev.keys():
419            if phase is 'REG':
420              continue
421            report += ', %f %s' % (dev[phase], phase)
422          logging.debug(report)
423
424
425    def _identify_driver(self, device):
426        """Return the driver name of a device (or "unknown")."""
427        for path, subdirs, _ in os.walk('/sys/devices'):
428            if device in subdirs:
429                node = os.path.join(path, device, 'driver')
430                if not os.path.exists(node):
431                    return "unknown"
432                return os.path.basename(os.path.realpath(node))
433        else:
434            return "unknown"
435
436
437    def _check_for_errors(self, ignore_kernel_warns):
438        """Find and identify suspend errors.
439
440        @param ignore_kernel_warns: Ignore kernel errors.
441
442        @returns: True iff we should retry.
443
444        @raises:
445          sys_power.KernelError: for non-allowlisted kernel failures.
446          sys_power.SuspendTimeout: took too long to enter suspend.
447          sys_power.SpuriousWakeupError: woke too soon from suspend.
448          sys_power.SuspendFailure: unidentified failure.
449        """
450        warning_regex = re.compile(r' kernel: \[.*WARNING:')
451        abort_regex = re.compile(r' kernel: \[.*Freezing of tasks abort'
452                r'| powerd_suspend\[.*Cancel suspend at kernel'
453                r'| powerd_suspend\[.*Warning: Device or resource busy on ' \
454                 'write to /sys/power/state')
455        # rsyslogd can put this out of order with dmesg, so track in variable
456        fail_regex = re.compile(r'powerd_suspend\[\d+\]: Error')
457        failed = False
458
459        # TODO(scottz): warning_monitor crosbug.com/38092
460        log_len = len(self._logs)
461        for i in xrange(log_len):
462            line = self._logs[i]
463            if warning_regex.search(line):
464                # match the source file from the WARNING line, and the
465                # actual error text by peeking one or two lines below that
466                src = cros_logging.strip_timestamp(line)
467                text = ''
468                if i+1 < log_len:
469                    text = cros_logging.strip_timestamp(self._logs[i + 1])
470                if i+2 < log_len:
471                    text += '\n' + cros_logging.strip_timestamp(
472                        self._logs[i + 2])
473                for p1, p2 in sys_power.KernelError.ALLOWLIST:
474                    if re.search(p1, src) and re.search(p2, text):
475                        logging.info('Allowlisted KernelError: %s', src)
476                        break
477                else:
478                    if ignore_kernel_warns:
479                        logging.warn('Non-allowlisted KernelError: %s', src)
480                    else:
481                        raise sys_power.KernelError("%s\n%s" % (src, text))
482            if abort_regex.search(line):
483                wake_source = 'unknown'
484                match = re.search(r'last active wakeup source: (.*)$',
485                        '\n'.join(self._logs[i-5:i+3]), re.MULTILINE)
486                if match:
487                    wake_source = match.group(1)
488                driver = self._identify_driver(wake_source)
489                for b, w in sys_power.SpuriousWakeupError.S0_ALLOWLIST:
490                    if (re.search(b, utils.get_board()) and
491                            re.search(w, wake_source)):
492                        logging.warning('Allowlisted spurious wake before '
493                                        'S3: %s | %s', wake_source, driver)
494                        return True
495                if "rtc" in driver:
496                    raise sys_power.SuspendTimeout('System took too '
497                                                   'long to suspend.')
498                raise sys_power.SpuriousWakeupError('Spurious wake '
499                        'before S3: %s | %s' % (wake_source, driver))
500            if fail_regex.search(line):
501                failed = True
502
503        if failed:
504            raise sys_power.SuspendFailure('Unidentified problem.')
505        return False
506
507
508    def _arc_resume_ts(self, retries=3):
509        """Parse arc logcat for arc resume timestamp.
510
511        @param retries: retry if the expected log cannot be found in logcat.
512
513        @returns: a float representing arc resume timestamp in  CPU seconds
514                  starting from the last boot if arc logcat resume log is parsed
515                  correctly; otherwise None.
516
517        """
518        command = 'android-sh -c "logcat -v monotonic -t 300 *:silent' \
519                  ' ArcPowerManagerService:D"'
520        regex_resume = re.compile(r'^\s*(\d+\.\d+).*ArcPowerManagerService: '
521                                  'Device finished resuming$')
522        for retry in xrange(retries + 1):
523            arc_logcat = utils.system_output(command, ignore_status=False)
524            arc_logcat = arc_logcat.splitlines()
525            for line in arc_logcat:
526                logging.debug('arc_resume: %s', line)
527                match_resume = regex_resume.search(line)
528                # ARC logcat is cleared before suspend so the first ARC resume
529                # timestamp is the one we are looking for.
530                if match_resume:
531                    return float(match_resume.group(1))
532            time.sleep(0.005 * 2**retry)
533        else:
534            logging.error('ARC did not resume correctly.')
535            return None
536
537
538    def get_suspend_delay(self):
539            return self._SUSPEND_DELAY.get(self._get_board(),
540                                           self._DEFAULT_SUSPEND_DELAY)
541
542
543    def suspend(self, duration=10, ignore_kernel_warns=False,
544                measure_arc=False):
545        """
546        Do a single suspend for 'duration' seconds. Estimates the amount of time
547        it takes to suspend for a board (see _SUSPEND_DELAY), so the actual RTC
548        wakeup delay will be longer. Returns None on errors, or raises the
549        exception when _throw is set. Returns a dict of general measurements,
550        or a tuple (general_measurements, individual_device_times) when
551        _device_times is set.
552
553        @param duration: time in seconds to do a suspend prior to waking.
554        @param ignore_kernel_warns: Ignore kernel errors.  Defaults to false.
555        """
556
557        if power_utils.get_sleep_state() == 'freeze':
558            arch = utils.get_arch()
559
560            if arch == 'x86_64':
561                self._s0ix_residency_stats = power_status.S0ixResidencyStats()
562            elif arch == 'aarch64':
563                self._s2idle_residency_stats = \
564                    power_status.S2IdleResidencyStats()
565
566        try:
567            iteration = len(self.failures) + len(self.successes) + 1
568            # Retry suspend in case we hit a known (allowlisted) bug
569            for _ in xrange(10):
570                # Clear powerd_suspend RTC timestamp, to avoid stale results.
571                utils.open_write_close(self.HWCLOCK_FILE, '')
572                self._reset_logs()
573                utils.system('sync')
574                board_delay = self.get_suspend_delay()
575                # Clear the ARC logcat to make parsing easier.
576                if measure_arc:
577                    command = 'android-sh -c "logcat -c"'
578                    utils.system(command, ignore_status=False)
579                try:
580                    # Return value of suspend method can be None
581                    alarm = self._suspend(duration + board_delay)
582                except sys_power.SpuriousWakeupError:
583                    # might be another error, we check for it ourselves below
584                    alarm = self._ALARM_FORCE_EARLY_WAKEUP
585
586                log_data = subprocess.check_output(['cbmem',
587                                                    '-1']).decode('utf-8')
588
589                for msg in re.findall(r'^.*ERROR.*$', log_data, re.M):
590                    for board, pattern in sys_power.FirmwareError.ALLOWLIST:
591                        if (re.search(board, utils.get_board())
592                                    and re.search(pattern, msg)):
593                            logging.info('Allowlisted FW error: %s', msg)
594                            break
595                    else:
596                        firmware_log = os.path.join(self._logdir,
597                                'firmware.log.' + str(iteration))
598                        with open(firmware_log, 'w') as f:
599                            f.write(log_data)
600                            logging.info('Saved firmware log: %s',
601                                         firmware_log)
602
603                        raise sys_power.FirmwareError(
604                                    msg.strip('\r\n '))
605
606                if not self._check_resume_finished():
607                    if not self._aborted_due_to_locking():
608                        raise error.TestError("Sanity check failed: did not try to suspend.")
609                    logging.warning('Aborted suspend due to power override, will retry\n')
610                    continue
611                if not self._check_for_errors(ignore_kernel_warns):
612                    hwclock_ts = self._hwclock_ts(alarm)
613                    if hwclock_ts:
614                        break
615
616            else:
617                raise error.TestWarn('Ten tries failed due to allowlisted bug')
618
619            # calculate general measurements
620            start_resume = self._ts('start_resume_time')
621            kernel_down = (self._ts('end_suspend_time') -
622                           self._ts('start_suspend_time'))
623            kernel_up = self._ts('end_resume_time') - start_resume
624            devices_up = self._device_resume_time()
625            firmware_up = self._firmware_resume_time()
626            # If we do not know the time at which the alarm went off, we cannot
627            # calculate the |total_up| and |board_up| time.
628            if alarm:
629                total_up = hwclock_ts - alarm
630                board_up = total_up - kernel_up - firmware_up
631            else:
632                total_up = -1
633                board_up = -1
634            try:
635                cpu_up = self._ts('cpu_ready_time', 0) - start_resume
636            except error.TestError:
637                # can be missing on non-SMP machines
638                cpu_up = None
639            if total_up > self._MAX_RESUME_TIME:
640                raise error.TestError('Sanity check failed: missed RTC wakeup.')
641
642            logging.info('Success(%d): %g down, %g up, %g board, %g firmware, '
643                         '%g kernel, %g cpu, %g devices',
644                         iteration, kernel_down, total_up, board_up,
645                         firmware_up, kernel_up, cpu_up, devices_up)
646
647            if hasattr(self, '_s0ix_residency_stats'):
648                s0ix_residency_secs = \
649                        self._s0ix_residency_stats.\
650                                get_accumulated_residency_secs()
651                cpu_uarch = utils.get_intel_cpu_uarch()
652                if not s0ix_residency_secs:
653                    msg = 'S0ix residency did not change.'
654                    if cpu_uarch not in self._IGNORE_S0IX_RESIDENCY_CHECK:
655                        raise sys_power.S0ixResidencyNotChanged(msg)
656                    logging.warn(msg)
657                logging.info('S0ix residency : %d secs.', s0ix_residency_secs)
658            elif hasattr(self, '_s2idle_residency_stats'):
659                s2idle_residency_usecs = \
660                        self._s2idle_residency_stats.\
661                                get_accumulated_residency_usecs()
662                if not s2idle_residency_usecs:
663                    msg = 's2idle residency did not change.'
664                    raise sys_power.S2IdleResidencyNotChanged(msg)
665
666                logging.info('s2idle residency : %d usecs.',
667                             s2idle_residency_usecs)
668
669            successful_suspend = {
670                'seconds_system_suspend': kernel_down,
671                'seconds_system_resume': total_up,
672                'seconds_system_resume_firmware': firmware_up + board_up,
673                'seconds_system_resume_firmware_cpu': firmware_up,
674                'seconds_system_resume_firmware_ec': board_up,
675                'seconds_system_resume_kernel': kernel_up,
676                'seconds_system_resume_kernel_cpu': cpu_up,
677                'seconds_system_resume_kernel_dev': devices_up,
678                }
679
680            if measure_arc:
681                arc_resume_ts = self._arc_resume_ts()
682                if arc_resume_ts:
683                    successful_suspend['seconds_system_resume_arc'] = \
684                        arc_resume_ts - start_resume
685
686            self.successes.append(successful_suspend)
687
688            if hasattr(self, 'device_times'):
689                self._individual_device_times(start_resume)
690                return (self.successes[-1], self.device_times[-1])
691            else:
692                return self.successes[-1]
693
694        except sys_power.SuspendFailure as ex:
695            message = '%s(%d): %s' % (type(ex).__name__, iteration, ex)
696            logging.error(message)
697            self.failures.append(ex)
698            if self._throw:
699                if type(ex).__name__ in ['KernelError', 'SuspendTimeout']:
700                    raise error.TestWarn(message)
701                else:
702                    raise error.TestFail(message)
703            return None
704
705
706    def finalize(self):
707        """Restore normal environment (not turning 3G back on for now...)"""
708        if os.path.exists(self.HWCLOCK_FILE):
709            os.remove(self.HWCLOCK_FILE)
710            if self._restart_tlsdated:
711                utils.system('initctl start tlsdated')
712            if self._reset_pm_print_times:
713                self._set_pm_print_times(False)
714        if hasattr(self, '_power_pref_changer'):
715            self._power_pref_changer.finalize()
716
717
718    def __del__(self):
719        self.finalize()
720