1 # Copyright (c) 2013 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 json 6 import logging 7 import math 8 import os 9 import pprint 10 import re 11 import StringIO 12 13 from autotest_lib.client.common_lib import error, utils 14 from autotest_lib.client.common_lib.cros import dev_server 15 from autotest_lib.server import afe_utils 16 17 18 TELEMETRY_RUN_BENCHMARKS_SCRIPT = 'tools/perf/run_benchmark' 19 TELEMETRY_RUN_CROS_TESTS_SCRIPT = 'chrome/test/telemetry/run_cros_tests' 20 TELEMETRY_RUN_GPU_TESTS_SCRIPT = 'content/test/gpu/run_gpu_test.py' 21 TELEMETRY_RUN_TESTS_SCRIPT = 'tools/telemetry/run_tests' 22 TELEMETRY_TIMEOUT_MINS = 120 23 24 # Result Statuses 25 SUCCESS_STATUS = 'SUCCESS' 26 WARNING_STATUS = 'WARNING' 27 FAILED_STATUS = 'FAILED' 28 29 # Regex for the RESULT output lines understood by chrome buildbot. 30 # Keep in sync with 31 # chromium/tools/build/scripts/slave/performance_log_processor.py. 32 RESULTS_REGEX = re.compile(r'(?P<IMPORTANT>\*)?RESULT ' 33 r'(?P<GRAPH>[^:]*): (?P<TRACE>[^=]*)= ' 34 r'(?P<VALUE>[\{\[]?[-\d\., ]+[\}\]]?)(' 35 r' ?(?P<UNITS>.+))?') 36 HISTOGRAM_REGEX = re.compile(r'(?P<IMPORTANT>\*)?HISTOGRAM ' 37 r'(?P<GRAPH>[^:]*): (?P<TRACE>[^=]*)= ' 38 r'(?P<VALUE_JSON>{.*})(?P<UNITS>.+)?') 39 40 41 class TelemetryResult(object): 42 """Class to represent the results of a telemetry run. 43 44 This class represents the results of a telemetry run, whether it ran 45 successful, failed or had warnings. 46 """ 47 48 49 def __init__(self, exit_code=0, stdout='', stderr=''): 50 """Initializes this TelemetryResultObject instance. 51 52 @param status: Status of the telemtry run. 53 @param stdout: Stdout of the telemetry run. 54 @param stderr: Stderr of the telemetry run. 55 """ 56 if exit_code == 0: 57 self.status = SUCCESS_STATUS 58 else: 59 self.status = FAILED_STATUS 60 61 # A list of perf values, e.g. 62 # [{'graph': 'graphA', 'trace': 'page_load_time', 63 # 'units': 'secs', 'value':0.5}, ...] 64 self.perf_data = [] 65 self._stdout = stdout 66 self._stderr = stderr 67 self.output = '\n'.join([stdout, stderr]) 68 69 70 def _cleanup_perf_string(self, str): 71 """Clean up a perf-related string by removing illegal characters. 72 73 Perf keys stored in the chromeOS database may contain only letters, 74 numbers, underscores, periods, and dashes. Transform an inputted 75 string so that any illegal characters are replaced by underscores. 76 77 @param str: The perf string to clean up. 78 79 @return The cleaned-up perf string. 80 """ 81 return re.sub(r'[^\w.-]', '_', str) 82 83 84 def _cleanup_units_string(self, units): 85 """Cleanup a units string. 86 87 Given a string representing units for a perf measurement, clean it up 88 by replacing certain illegal characters with meaningful alternatives. 89 Any other illegal characters should then be replaced with underscores. 90 91 Examples: 92 count/time -> count_per_time 93 % -> percent 94 units! --> units_ 95 score (bigger is better) -> score__bigger_is_better_ 96 score (runs/s) -> score__runs_per_s_ 97 98 @param units: The units string to clean up. 99 100 @return The cleaned-up units string. 101 """ 102 if '%' in units: 103 units = units.replace('%', 'percent') 104 if '/' in units: 105 units = units.replace('/','_per_') 106 return self._cleanup_perf_string(units) 107 108 109 def parse_benchmark_results(self): 110 """Parse the results of a telemetry benchmark run. 111 112 Stdout has the output in RESULT block format below. 113 114 The lines of interest start with the substring "RESULT". These are 115 specially-formatted perf data lines that are interpreted by chrome 116 builbot (when the Telemetry tests run for chrome desktop) and are 117 parsed to extract perf data that can then be displayed on a perf 118 dashboard. This format is documented in the docstring of class 119 GraphingLogProcessor in this file in the chrome tree: 120 121 chromium/tools/build/scripts/slave/process_log_utils.py 122 123 Example RESULT output lines: 124 RESULT average_commit_time_by_url: http___www.ebay.com= 8.86528 ms 125 RESULT CodeLoad: CodeLoad= 6343 score (bigger is better) 126 RESULT ai-astar: ai-astar= [614,527,523,471,530,523,577,625,614,538] ms 127 128 Currently for chromeOS, we can only associate a single perf key (string) 129 with a perf value. That string can only contain letters, numbers, 130 dashes, periods, and underscores, as defined by write_keyval() in: 131 132 chromeos/src/third_party/autotest/files/client/common_lib/ 133 base_utils.py 134 135 We therefore parse each RESULT line, clean up the strings to remove any 136 illegal characters not accepted by chromeOS, and construct a perf key 137 string based on the parsed components of the RESULT line (with each 138 component separated by a special delimiter). We prefix the perf key 139 with the substring "TELEMETRY" to identify it as a telemetry-formatted 140 perf key. 141 142 Stderr has the format of Warnings/Tracebacks. There is always a default 143 warning of the display enviornment setting, followed by warnings of 144 page timeouts or a traceback. 145 146 If there are any other warnings we flag the test as warning. If there 147 is a traceback we consider this test a failure. 148 """ 149 if not self._stdout: 150 # Nothing in stdout implies a test failure. 151 logging.error('No stdout, test failed.') 152 self.status = FAILED_STATUS 153 return 154 155 stdout_lines = self._stdout.splitlines() 156 for line in stdout_lines: 157 results_match = RESULTS_REGEX.search(line) 158 histogram_match = HISTOGRAM_REGEX.search(line) 159 if results_match: 160 self._process_results_line(results_match) 161 elif histogram_match: 162 self._process_histogram_line(histogram_match) 163 164 pp = pprint.PrettyPrinter(indent=2) 165 logging.debug('Perf values: %s', pp.pformat(self.perf_data)) 166 167 if self.status is SUCCESS_STATUS: 168 return 169 170 # Otherwise check if simply a Warning occurred or a Failure, 171 # i.e. a Traceback is listed. 172 self.status = WARNING_STATUS 173 for line in self._stderr.splitlines(): 174 if line.startswith('Traceback'): 175 self.status = FAILED_STATUS 176 177 def _process_results_line(self, line_match): 178 """Processes a line that matches the standard RESULT line format. 179 180 Args: 181 line_match: A MatchObject as returned by re.search. 182 """ 183 match_dict = line_match.groupdict() 184 graph_name = self._cleanup_perf_string(match_dict['GRAPH'].strip()) 185 trace_name = self._cleanup_perf_string(match_dict['TRACE'].strip()) 186 units = self._cleanup_units_string( 187 (match_dict['UNITS'] or 'units').strip()) 188 value = match_dict['VALUE'].strip() 189 unused_important = match_dict['IMPORTANT'] or False # Unused now. 190 191 if value.startswith('['): 192 # A list of values, e.g., "[12,15,8,7,16]". Extract just the 193 # numbers, compute the average and use that. In this example, 194 # we'd get 12+15+8+7+16 / 5 --> 11.6. 195 value_list = [float(x) for x in value.strip('[],').split(',')] 196 value = float(sum(value_list)) / len(value_list) 197 elif value.startswith('{'): 198 # A single value along with a standard deviation, e.g., 199 # "{34.2,2.15}". Extract just the value itself and use that. 200 # In this example, we'd get 34.2. 201 value_list = [float(x) for x in value.strip('{},').split(',')] 202 value = value_list[0] # Position 0 is the value. 203 elif re.search('^\d+$', value): 204 value = int(value) 205 else: 206 value = float(value) 207 208 self.perf_data.append({'graph':graph_name, 'trace': trace_name, 209 'units': units, 'value': value}) 210 211 def _process_histogram_line(self, line_match): 212 """Processes a line that matches the HISTOGRAM line format. 213 214 Args: 215 line_match: A MatchObject as returned by re.search. 216 """ 217 match_dict = line_match.groupdict() 218 graph_name = self._cleanup_perf_string(match_dict['GRAPH'].strip()) 219 trace_name = self._cleanup_perf_string(match_dict['TRACE'].strip()) 220 units = self._cleanup_units_string( 221 (match_dict['UNITS'] or 'units').strip()) 222 histogram_json = match_dict['VALUE_JSON'].strip() 223 unused_important = match_dict['IMPORTANT'] or False # Unused now. 224 histogram_data = json.loads(histogram_json) 225 226 # Compute geometric mean 227 count = 0 228 sum_of_logs = 0 229 for bucket in histogram_data['buckets']: 230 mean = (bucket['low'] + bucket['high']) / 2.0 231 if mean > 0: 232 sum_of_logs += math.log(mean) * bucket['count'] 233 count += bucket['count'] 234 235 value = math.exp(sum_of_logs / count) if count > 0 else 0.0 236 237 self.perf_data.append({'graph':graph_name, 'trace': trace_name, 238 'units': units, 'value': value}) 239 240 class TelemetryRunner(object): 241 """Class responsible for telemetry for a given build. 242 243 This class will extract and install telemetry on the devserver and is 244 responsible for executing the telemetry benchmarks and returning their 245 output to the caller. 246 """ 247 248 def __init__(self, host, local=False): 249 """Initializes this telemetry runner instance. 250 251 If telemetry is not installed for this build, it will be. 252 253 @param host: Host where the test will be run. 254 @param local: If set, no devserver will be used, test will be run 255 locally. 256 """ 257 self._host = host 258 self._devserver = None 259 self._telemetry_path = None 260 # TODO (llozano crbug.com/324964). Remove conditional code. 261 # Use a class hierarchy instead. 262 if local: 263 self._setup_local_telemetry() 264 else: 265 self._setup_devserver_telemetry() 266 267 logging.debug('Telemetry Path: %s', self._telemetry_path) 268 269 270 def _setup_devserver_telemetry(self): 271 """Setup Telemetry to use the devserver.""" 272 logging.debug('Setting up telemetry for devserver testing') 273 logging.debug('Grabbing build from AFE.') 274 275 build = afe_utils.get_build(self._host) 276 if not build: 277 logging.error('Unable to locate build label for host: %s.', 278 self._host.hostname) 279 raise error.AutotestError('Failed to grab build for host %s.' % 280 self._host.hostname) 281 282 logging.debug('Setting up telemetry for build: %s', build) 283 284 self._devserver = dev_server.ImageServer.resolve(build) 285 self._devserver.stage_artifacts(build, ['autotest_packages']) 286 self._telemetry_path = self._devserver.setup_telemetry(build=build) 287 288 289 def _setup_local_telemetry(self): 290 """Setup Telemetry to use local path to its sources. 291 292 First look for chrome source root, either externally mounted, or inside 293 the chroot. Prefer chrome-src-internal source tree to chrome-src. 294 """ 295 TELEMETRY_DIR = 'src' 296 CHROME_LOCAL_SRC = '/var/cache/chromeos-cache/distfiles/target/' 297 CHROME_EXTERNAL_SRC = os.path.expanduser('~/chrome_root/') 298 299 logging.debug('Setting up telemetry for local testing') 300 301 sources_list = ('chrome-src-internal', 'chrome-src') 302 dir_list = [CHROME_EXTERNAL_SRC] 303 dir_list.extend( 304 [os.path.join(CHROME_LOCAL_SRC, x) for x in sources_list]) 305 if 'CHROME_ROOT' in os.environ: 306 dir_list.insert(0, os.environ['CHROME_ROOT']) 307 308 telemetry_src = '' 309 for dir in dir_list: 310 if os.path.exists(dir): 311 telemetry_src = os.path.join(dir, TELEMETRY_DIR) 312 break 313 else: 314 raise error.TestError('Telemetry source directory not found.') 315 316 self._devserver = None 317 self._telemetry_path = telemetry_src 318 319 320 def _get_telemetry_cmd(self, script, test_or_benchmark, *args): 321 """Build command to execute telemetry based on script and benchmark. 322 323 @param script: Telemetry script we want to run. For example: 324 [path_to_telemetry_src]/src/tools/telemetry/run_tests. 325 @param test_or_benchmark: Name of the test or benchmark we want to run, 326 with the page_set (if required) as part of 327 the string. 328 @param args: additional list of arguments to pass to the script. 329 330 @returns Full telemetry command to execute the script. 331 """ 332 telemetry_cmd = [] 333 if self._devserver: 334 devserver_hostname = self._devserver.url().split( 335 'http://')[1].split(':')[0] 336 telemetry_cmd.extend(['ssh', devserver_hostname]) 337 338 telemetry_cmd.extend( 339 ['python', 340 script, 341 '--verbose', 342 '--browser=cros-chrome', 343 '--remote=%s' % self._host.hostname]) 344 telemetry_cmd.extend(args) 345 telemetry_cmd.append(test_or_benchmark) 346 347 return telemetry_cmd 348 349 350 def _run_telemetry(self, script, test_or_benchmark, *args): 351 """Runs telemetry on a dut. 352 353 @param script: Telemetry script we want to run. For example: 354 [path_to_telemetry_src]/src/tools/telemetry/run_tests. 355 @param test_or_benchmark: Name of the test or benchmark we want to run, 356 with the page_set (if required) as part of the 357 string. 358 @param args: additional list of arguments to pass to the script. 359 360 @returns A TelemetryResult Instance with the results of this telemetry 361 execution. 362 """ 363 # TODO (sbasi crbug.com/239933) add support for incognito mode. 364 365 telemetry_cmd = self._get_telemetry_cmd(script, 366 test_or_benchmark, 367 *args) 368 logging.debug('Running Telemetry: %s', ' '.join(telemetry_cmd)) 369 370 output = StringIO.StringIO() 371 error_output = StringIO.StringIO() 372 exit_code = 0 373 try: 374 result = utils.run(' '.join(telemetry_cmd), stdout_tee=output, 375 stderr_tee=error_output, 376 timeout=TELEMETRY_TIMEOUT_MINS*60) 377 exit_code = result.exit_status 378 except error.CmdError as e: 379 # Telemetry returned a return code of not 0; for benchmarks this 380 # can be due to a timeout on one of the pages of the page set and 381 # we may still have data on the rest. For a test however this 382 # indicates failure. 383 logging.debug('Error occurred executing telemetry.') 384 exit_code = e.result_obj.exit_status 385 386 stdout = output.getvalue() 387 stderr = error_output.getvalue() 388 logging.debug('Telemetry completed with exit code: %d.\nstdout:%s\n' 389 'stderr:%s', exit_code, stdout, stderr) 390 391 return TelemetryResult(exit_code=exit_code, stdout=stdout, 392 stderr=stderr) 393 394 395 def _run_test(self, script, test, *args): 396 """Runs a telemetry test on a dut. 397 398 @param script: Which telemetry test script we want to run. Can be 399 telemetry's base test script or the Chrome OS specific 400 test script. 401 @param test: Telemetry test we want to run. 402 @param args: additional list of arguments to pass to the script. 403 404 @returns A TelemetryResult Instance with the results of this telemetry 405 execution. 406 """ 407 logging.debug('Running telemetry test: %s', test) 408 telemetry_script = os.path.join(self._telemetry_path, script) 409 result = self._run_telemetry(telemetry_script, test, *args) 410 if result.status is FAILED_STATUS: 411 raise error.TestFail('Telemetry test %s failed.' % test) 412 return result 413 414 415 def run_telemetry_test(self, test, *args): 416 """Runs a telemetry test on a dut. 417 418 @param test: Telemetry test we want to run. 419 @param args: additional list of arguments to pass to the telemetry 420 execution script. 421 422 @returns A TelemetryResult Instance with the results of this telemetry 423 execution. 424 """ 425 return self._run_test(TELEMETRY_RUN_TESTS_SCRIPT, test, *args) 426 427 428 def run_cros_telemetry_test(self, test, *args): 429 """Runs a cros specific telemetry test on a dut. 430 431 @param test: Telemetry test we want to run. 432 @param args: additional list of arguments to pass to the telemetry 433 execution script. 434 435 @returns A TelemetryResult instance with the results of this telemetry 436 execution. 437 """ 438 return self._run_test(TELEMETRY_RUN_CROS_TESTS_SCRIPT, test, *args) 439 440 441 def run_gpu_test(self, test, *args): 442 """Runs a gpu test on a dut. 443 444 @param test: Gpu test we want to run. 445 @param args: additional list of arguments to pass to the telemetry 446 execution script. 447 448 @returns A TelemetryResult instance with the results of this telemetry 449 execution. 450 """ 451 return self._run_test(TELEMETRY_RUN_GPU_TESTS_SCRIPT, test, *args) 452 453 454 @staticmethod 455 def _output_perf_value(perf_value_writer, perf_data): 456 """Output perf values to result dir. 457 458 The perf values will be output to the result dir and 459 be subsequently uploaded to perf dashboard. 460 461 @param perf_value_writer: Should be an instance with the function 462 output_perf_value(), if None, no perf value 463 will be written. Typically this will be the 464 job object from an autotest test. 465 @param perf_data: A list of perf values, each value is 466 a dictionary that looks like 467 {'graph':'GraphA', 'trace':'metric1', 468 'units':'secs', 'value':0.5} 469 """ 470 for perf_value in perf_data: 471 perf_value_writer.output_perf_value( 472 description=perf_value['trace'], 473 value=perf_value['value'], 474 units=perf_value['units'], 475 graph=perf_value['graph']) 476 477 478 def run_telemetry_benchmark(self, benchmark, perf_value_writer=None, 479 *args): 480 """Runs a telemetry benchmark on a dut. 481 482 @param benchmark: Benchmark we want to run. 483 @param perf_value_writer: Should be an instance with the function 484 output_perf_value(), if None, no perf value 485 will be written. Typically this will be the 486 job object from an autotest test. 487 @param args: additional list of arguments to pass to the telemetry 488 execution script. 489 490 @returns A TelemetryResult Instance with the results of this telemetry 491 execution. 492 """ 493 logging.debug('Running telemetry benchmark: %s', benchmark) 494 telemetry_script = os.path.join(self._telemetry_path, 495 TELEMETRY_RUN_BENCHMARKS_SCRIPT) 496 result = self._run_telemetry(telemetry_script, benchmark, *args) 497 result.parse_benchmark_results() 498 499 if perf_value_writer: 500 self._output_perf_value(perf_value_writer, result.perf_data) 501 502 if result.status is WARNING_STATUS: 503 raise error.TestWarn('Telemetry Benchmark: %s' 504 ' exited with Warnings.' % benchmark) 505 if result.status is FAILED_STATUS: 506 raise error.TestFail('Telemetry Benchmark: %s' 507 ' failed to run.' % benchmark) 508 509 return result 510
