• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
1# Lint as: python2, python3
2# Copyright 2018 The Chromium OS Authors. All rights reserved.
3# Use of this source code is governed by a BSD-style license that can be
4# found in the LICENSE file.
5
6import codecs
7import logging
8import os
9import re
10import shutil
11import time
12
13from autotest_lib.client.bin import test, utils
14from autotest_lib.client.cros import cryptohome
15from autotest_lib.client.common_lib import error
16from autotest_lib.client.common_lib.cros import chrome
17
18RE_ATTESTATION = 'Prepared successfully \((\d+)ms\)'
19BOOT_TIMES_CMD = 'bootstat_summary'
20BOOT_TIMES_DUMP_NAME = 'bootstat_summary'
21
22def is_attestation_prepared():
23    """Checks if attestation is prepared on the device.
24
25    @return: Attestation readiness status - True/False.
26
27    """
28    return cryptohome.get_tpm_attestation_status().get(
29            'prepared_for_enrollment', False)
30
31
32def get_bootstat_timestamp(name, occurrence):
33    """Gets the timestamp in ms of the given timestamp name and occurrence
34
35    bootstat_summary output contains multiple lines. The first line are headers,
36    and the rest are stats for event occurrences, one occurrence per line.
37
38    @param name: Name of the timestamp.
39    @param occurrence: Defines which occurrence of the timestamp should
40                       be returned. The occurrence number is 1-based, and -1
41                       means the latest occurrence.
42
43    @return: Timestamp in ms or -1.0 if the requested occurrence doesn't exist.
44    """
45    try:
46        output = utils.system_output('bootstat_summary %s' % name).splitlines()
47        stats = float(output[occurrence].split()[0])
48    except Exception:
49        stats = -1.0
50
51    return stats
52
53def uptime_from_timestamp(name, occurrence=-1):
54    """Extract the uptime in seconds for the captured timestamp.
55
56    @param name: Name of the timestamp.
57    @param occurrence: Defines which occurrence of the timestamp should
58                       be returned. The occurrence number is 1-based.
59                       Useful if it can be recorded multiple times.
60                       Default: use the last one (-1).
61    @raises error.TestFail: Raised if the requested timestamp doesn't exist.
62
63    @return: Uptime in seconds.
64
65    """
66    timestamp = utils.wait_for_value(
67        lambda: get_bootstat_timestamp(name, occurrence),
68        max_threshold=0.001,
69        timeout_sec=10)
70
71    if timestamp < 0:
72        raise error.TestFail('Failed to get timestamp for %s at occurrence %d.'
73                             % (name, occurrence))
74
75    return timestamp / 1000
76
77def diff_timestamp(start, end):
78    """Return the time difference between the two timestamps in seconds.
79       Takes the last occurrence of each timestamp if multiple are available.
80
81    @param start: The earlier timestamp.
82    @param end: The later timestamp.
83
84    @return: Difference in seconds.
85
86    """
87    return uptime_from_timestamp(end) - uptime_from_timestamp(start)
88
89def get_duration(pattern, line):
90    """Extract duration reported in syslog line.
91
92    @param pattern: Regular expression, 1st group of which contains the
93                    duration in ms.
94    @param liner: Line from syslog.
95
96    @return: Duration in seconds.
97
98    """
99    m = re.search(pattern, line)
100    if not m:
101        raise error.TestFail('Cannot get duration from %r', line)
102    return float(m.group(1)) / 1000
103
104class platform_InitLoginPerf(test.test):
105    """Test to exercise and gather perf data for initialization and login."""
106
107    version = 1
108
109    def shall_init(self):
110        """Check if this test shall perform and measure initialization.
111
112        @return: True if yes, False otherwise.
113
114        """
115        return self.perform_init
116
117    def save_file(self, name):
118        """Save a single file to the results directory of the test.
119
120        @param name: Name of the file.
121
122        """
123        shutil.copy(name, self.resultsdir)
124
125    def save_cmd_output(self, cmd, name):
126        """Save output of a command to the results directory of the test.
127
128        @param cmd: Command to run.
129        @param name: Name of the file to save to.
130
131        """
132        utils.system('%s > %s/%s' % (cmd, self.resultsdir, name))
133
134    def wait_for_file(self, name, timeout=120):
135        """Wait until a file is created.
136
137           @param name: File name.
138           @param timeout: Timeout waiting for the file.
139           @raises error.TestFail: Raised in case of timeout.
140
141        """
142        if not utils.wait_for_value(lambda: os.path.isfile(name),
143                                    expected_value=True,
144                                    timeout_sec=timeout):
145            raise error.TestFail('Timeout waiting for %r' % name)
146
147    def wait_for_cryptohome_readiness(self):
148        """Wait until cryptohome has started and initialized system salt."""
149        self.wait_for_file('/home/.shadow/salt')
150
151    def run_pre_login(self):
152        """Run pre-login steps.
153           1) Wait for cryptohome readiness (salt created).
154           2) Trigger initialization (take ownership), if requested.
155           3) Perform a pre-login delay, if requested.
156
157           @param timeout: Timeout waiting for cryptohome first start.
158           @raises error.TestFail: Raised in case of timeout.
159
160        """
161        self.wait_for_cryptohome_readiness()
162        if self.shall_init():
163            time.sleep(self.pre_init_delay)
164            cryptohome.take_tpm_ownership(wait_for_ownership=False)
165
166    def get_login_duration(self):
167        """Extract login duration from recorded timestamps."""
168        self.results['login-duration'] = diff_timestamp('login-prompt-visible',
169                                                        'login-success')
170
171    def wait_for_attestation_prepared(self, timeout=120):
172        """Wait until attestation is prepared, i.e.
173           AttestationPrepareForEnrollment init stage is done.
174
175           @param timeout: Timeout waiting for attestation to be
176                           prepared.
177           @raises error.TestFail: Raised in case of timeout.
178
179        """
180        if not utils.wait_for_value(is_attestation_prepared,
181                                    expected_value=True,
182                                    timeout_sec=timeout):
183            logging.debug('tpm_more_status: %r',
184                          cryptohome.get_tpm_attestation_status())
185            raise error.TestFail('Timeout waiting for attestation_prepared')
186
187    def get_init_durations(self):
188        """Extract init stage durations from syslog.
189
190           @raises error.TestFail: Raised if duration lines were not found in
191                                   syslog.
192
193        """
194        # Grep syslog for AttestationReady line
195        attestation_line = ''
196        with codecs.open('/var/log/messages',
197                         'r',
198                         encoding='utf-8',
199                         errors='surrogateescape') as syslog:
200            for ln in syslog:
201                if 'Attestation: Prepared successfully' in ln:
202                    attestation_line = ln
203        logging.debug('Attestation prepared: %r', attestation_line)
204        if (not attestation_line):
205            raise error.TestFail('Could not find duration lines in syslog')
206
207        self.results['attestation-duration'] = get_duration(RE_ATTESTATION,
208                                                            attestation_line)
209
210    def run_post_login(self):
211        """Run post-login steps.
212           If initialization shall be performed: wait for attestation readiness
213           and extract durations of initialization stages from syslog.
214        """
215        self.get_login_duration()
216        self.save_cmd_output(BOOT_TIMES_CMD, BOOT_TIMES_DUMP_NAME)
217        if self.shall_init():
218            self.wait_for_attestation_prepared()
219            self.get_init_durations()
220
221    def run_once(self, perform_init=False, pre_init_delay=0):
222        """Run the test.
223
224        @param perform_init: Specifies if initialization shall be performed
225                             to measure first boot performance.
226        @param pre_init_delay: Delay before starting initialization.
227
228        """
229        self.perform_init = perform_init
230        self.pre_init_delay = pre_init_delay
231        self.results = {}
232
233        self.run_pre_login()
234        with chrome.Chrome(auto_login=True):
235            self.run_post_login()
236
237        logging.info('Results: %s', self.results)
238        self.write_perf_keyval(self.results)
239