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