1#! /usr/bin/env python3 2# 3# Copyright 2021 The ANGLE Project Authors. All rights reserved. 4# Use of this source code is governed by a BSD-style license that can be 5# found in the LICENSE file. 6# 7''' 8Pixel 6 (ARM based) specific script that measures the following for each restricted_trace: 9- Wall time per frame 10- GPU time per frame (if run with --vsync) 11- CPU time per frame 12- GPU power per frame 13- CPU power per frame 14- GPU memory per frame 15 16Setup: 17 18 autoninja -C out/<config> angle_trace_perf_tests angle_apks 19 adb install -r --force-queryable ./out/<config>/apks/AngleLibraries.apk 20 adb install -r out/<config>/angle_trace_tests_apk/angle_trace_tests-debug.apk 21 (cd out/<config>; ../../src/tests/run_angle_android_test.py angle_trace_tests \ 22 --verbose --local-output --verbose-logging --max-steps-performed 1 --log=debug) 23 24Recommended command to run: 25 26 python3 restricted_trace_perf.py --fixedtime 10 --power --output-tag android.$(date '+%Y%m%d') --loop-count 5 27 28- This will run through all the traces 5 times with the native driver, then 5 times with vulkan (via ANGLE) 29- 10 second run time with one warmup loop 30 31Output will be printed to the terminal as it is collected. 32 33Of the 5 runs, the high and low for each data point will be dropped, average of the remaining three will be tracked in the summary spreadsheet. 34''' 35 36import argparse 37import copy 38import csv 39import fcntl 40import fnmatch 41import json 42import logging 43import os 44import re 45import statistics 46import subprocess 47import sys 48import threading 49import time 50 51from collections import defaultdict, namedtuple 52from datetime import datetime 53from psutil import process_iter 54 55DEFAULT_TEST_DIR = '.' 56DEFAULT_TEST_JSON = 'restricted_traces.json' 57DEFAULT_LOG_LEVEL = 'info' 58 59Result = namedtuple('Result', ['stdout', 'stderr', 'time']) 60 61 62def run_command(args): 63 logging.debug('Running %s' % args) 64 65 start_time = time.time() 66 67 try: 68 process = subprocess.Popen( 69 args, 70 shell=True, 71 stdout=subprocess.PIPE, 72 stderr=subprocess.PIPE, 73 universal_newlines=True) 74 except subprocess.CalledProcessError as e: 75 raise RuntimeError("command '{}' return with error (code {}): {}".format( 76 e.cmd, e.returncode, e.output)) 77 78 stdout, stderr = process.communicate() 79 80 time_elapsed = time.time() - start_time 81 82 return Result(stdout, stderr, time_elapsed) 83 84 85def run_async_command(args): 86 logging.debug('Kicking off subprocess %s' % (args)) 87 88 try: 89 async_process = subprocess.Popen( 90 args, 91 stdout=subprocess.PIPE, 92 stderr=subprocess.STDOUT, 93 shell=True, 94 universal_newlines=True) 95 except subprocess.CalledProcessError as e: 96 raise RuntimeError("command '{}' return with error (code {}): {}".format( 97 e.cmd, e.returncode, e.output)) 98 99 logging.debug('Done launching subprocess') 100 101 return async_process 102 103 104def run_adb_command(args): 105 return run_command('adb ' + args) 106 107 108def run_async_adb_command(args): 109 return run_async_command('adb ' + args) 110 111 112def cleanup(): 113 run_adb_command('shell rm -f /sdcard/Download/out.txt /sdcard/Download/gpumem.txt') 114 115 116def clear_blob_cache(): 117 run_adb_command( 118 'shell run-as com.android.angle.test rm -rf /data/user_de/0/com.android.angle.test/cache') 119 120 121def select_device(device_arg): 122 # The output from 'adb devices' always includes a header and a new line at the end. 123 result_dev = run_command('adb devices') 124 result_dev_out = result_dev.stdout.strip() 125 126 result_header_end = result_dev_out.find('\n') 127 result_dev_out = '' if result_header_end == -1 else result_dev_out[result_header_end:] 128 result_dev_out = result_dev_out.split()[0::2] 129 130 def print_device_list(): 131 print('\nList of available devices:\n{}'.format('\n'.join(result_dev_out))) 132 133 num_connected_devices = len(result_dev_out) 134 135 # Check the device arg first. If there is none, use the ANDROID SERIAL env var. 136 android_serial_env = os.environ.get('ANDROID_SERIAL') 137 device_serial = device_arg if device_arg != '' else android_serial_env 138 139 # Check for device exceptions 140 if num_connected_devices == 0: 141 logging.error('DeviceError: No devices detected. Please connect a device and try again.') 142 exit() 143 144 if num_connected_devices > 1 and device_serial is None: 145 logging.error( 146 'DeviceError: More than one device detected. Please specify a target device\n' 147 'through either the --device option or $ANDROID_SERIAL, and try again.') 148 print_device_list() 149 exit() 150 151 if device_serial is not None and device_serial not in result_dev_out: 152 logging.error('DeviceError: Device with serial {} not detected.'.format(device_serial)) 153 if device_arg != '': 154 logging.error('Please update the --device input and try again.') 155 else: 156 logging.error('Please update $ANDROID_SERIAL and try again.') 157 print_device_list() 158 exit() 159 160 # Select device 161 if device_serial is not None: 162 logging.info('Device with serial {} selected.'.format(device_serial)) 163 os.environ['ANDROID_SERIAL'] = device_serial 164 165 else: 166 logging.info('Default device ({}) selected.'.format(result_dev_out[0])) 167 168 169def get_mode(args): 170 mode = '' 171 if args.vsync: 172 mode = 'vsync' 173 elif args.offscreen: 174 mode = 'offscreen' 175 176 return mode 177 178 179def get_trace_width(mode): 180 width = 40 181 if mode == 'vsync': 182 width += 5 183 elif mode == 'offscreen': 184 width += 10 185 186 return width 187 188 189def run_trace(trace, args): 190 mode = get_mode(args) 191 192 # Kick off a subprocess that collects peak gpu memory periodically 193 # Note the 0.25 below is the delay (in seconds) between memory checks 194 if args.memory: 195 run_adb_command('push gpumem.sh /data/local/tmp') 196 memory_command = 'shell sh /data/local/tmp/gpumem.sh 0.25' 197 memory_process = run_async_adb_command(memory_command) 198 199 flags = [ 200 '--gtest_filter=TraceTest.' + trace, '--use-gl=native', '--verbose', '--verbose-logging' 201 ] 202 if mode != '': 203 flags.append('--' + mode) 204 if args.maxsteps != '': 205 flags += ['--max-steps-performed', args.maxsteps] 206 if args.fixedtime != '': 207 flags += ['--fixed-test-time-with-warmup', args.fixedtime] 208 if args.minimizegpuwork: 209 flags.append('--minimize-gpu-work') 210 211 # Build a command that can be run directly over ADB, for example: 212 r''' 213adb shell am instrument -w \ 214 -e org.chromium.native_test.NativeTestInstrumentationTestRunner.StdoutFile /sdcard/Download/out.txt \ 215 -e org.chromium.native_test.NativeTest.CommandLineFlags \ 216 "--gtest_filter=TraceTest.empires_and_puzzles\ --use-angle=vulkan\ --screenshot-dir\ /sdcard\ --screenshot-frame\ 2\ --max-steps-performed\ 2\ --no-warmup" \ 217 -e org.chromium.native_test.NativeTestInstrumentationTestRunner.ShardNanoTimeout "1000000000000000000" \ 218 -e org.chromium.native_test.NativeTestInstrumentationTestRunner.NativeTestActivity com.android.angle.test.AngleUnitTestActivity \ 219 com.android.angle.test/org.chromium.build.gtest_apk.NativeTestInstrumentationTestRunner 220 ''' 221 adb_command = r''' 222shell am instrument -w \ 223 -e org.chromium.native_test.NativeTestInstrumentationTestRunner.StdoutFile /sdcard/Download/out.txt \ 224 -e org.chromium.native_test.NativeTest.CommandLineFlags "{flags}" \ 225 -e org.chromium.native_test.NativeTestInstrumentationTestRunner.ShardNanoTimeout "1000000000000000000" \ 226 -e org.chromium.native_test.NativeTestInstrumentationTestRunner.NativeTestActivity \ 227 com.android.angle.test.AngleUnitTestActivity \ 228 com.android.angle.test/org.chromium.build.gtest_apk.NativeTestInstrumentationTestRunner 229 '''.format(flags=r'\ '.join(flags)).strip() # Note: space escaped due to subprocess shell=True 230 231 result = run_adb_command(adb_command) 232 233 if args.memory: 234 logging.debug('Killing gpumem subprocess') 235 memory_process.kill() 236 237 return result.time 238 239 240def get_test_time(): 241 # Pull the results from the device and parse 242 result = run_adb_command('shell cat /sdcard/Download/out.txt | grep -v Error | grep -v Frame') 243 244 measured_time = None 245 246 for line in result.stdout.splitlines(): 247 logging.debug('Checking line: %s' % line) 248 249 # Look for this line and grab the second to last entry: 250 # Mean result time: 1.2793 ms 251 if "Mean result time" in line: 252 measured_time = line.split()[-2] 253 break 254 255 # Check for skipped tests 256 if "Test skipped due to missing extension" in line: 257 missing_ext = line.split()[-1] 258 logging.debug('Skipping test due to missing extension: %s' % missing_ext) 259 measured_time = missing_ext 260 break 261 262 if measured_time is None: 263 if '[ PASSED ]' in result.stdout: 264 measured_time = 'missing' 265 else: 266 measured_time = 'crashed' 267 268 return measured_time 269 270 271def get_gpu_memory(trace_duration): 272 # Pull the results from the device and parse 273 result = run_adb_command('shell cat /sdcard/Download/gpumem.txt | awk "NF"') 274 275 # The gpumem script grabs snapshots of memory per process 276 # Output looks like this, repeated once per sleep_duration of the test: 277 # 278 # time_elapsed: 9 279 # com.android.angle.test:test_process 16513 280 # Memory snapshot for GPU 0: 281 # Global total: 516833280 282 # Proc 504 total: 170385408 283 # Proc 1708 total: 33767424 284 # Proc 2011 total: 17018880 285 # Proc 16513 total: 348479488 286 # Proc 27286 total: 20877312 287 # Proc 27398 total: 1028096 288 289 # Gather the memory at each snapshot 290 time_elapsed = '' 291 test_process = '' 292 gpu_mem = [] 293 gpu_mem_sustained = [] 294 for line in result.stdout.splitlines(): 295 logging.debug('Checking line: %s' % line) 296 297 if "time_elapsed" in line: 298 time_elapsed = line.split()[-1] 299 logging.debug('time_elapsed: %s' % time_elapsed) 300 continue 301 302 # Look for this line and grab the last entry: 303 # com.android.angle.test:test_process 31933 304 if "com.android.angle.test" in line: 305 test_process = line.split()[-1] 306 logging.debug('test_process: %s' % test_process) 307 continue 308 309 # If we don't know test process yet, break 310 if test_process == '': 311 continue 312 313 # If we made it this far, we have the process id 314 315 # Look for this line and grab the last entry: 316 # Proc 31933 total: 235184128 317 if test_process in line: 318 gpu_mem_entry = line.split()[-1] 319 logging.debug('Adding: %s to gpu_mem' % gpu_mem_entry) 320 gpu_mem.append(int(gpu_mem_entry)) 321 # logging.debug('gpu_mem contains: %i' % ' '.join(gpu_mem)) 322 if safe_cast_float(time_elapsed) >= (safe_cast_float(trace_duration) / 2): 323 # Start tracking sustained memory usage at the half way point 324 logging.debug('Adding: %s to gpu_mem_sustained' % gpu_mem_entry) 325 gpu_mem_sustained.append(int(gpu_mem_entry)) 326 continue 327 328 gpu_mem_max = 0 329 if len(gpu_mem) != 0: 330 gpu_mem_max = max(gpu_mem) 331 332 gpu_mem_average = 0 333 if len(gpu_mem_sustained) != 0: 334 gpu_mem_average = statistics.mean(gpu_mem_sustained) 335 336 return gpu_mem_average, gpu_mem_max 337 338 339def get_proc_memory(): 340 # Pull the results from the device and parse 341 result = run_adb_command('shell cat /sdcard/Download/out.txt') 342 memory_median = '' 343 memory_max = '' 344 345 for line in result.stdout.splitlines(): 346 # Look for "memory_max" in the line and grab the second to last entry: 347 logging.debug('Checking line: %s' % line) 348 349 if "memory_median" in line: 350 memory_median = line.split()[-2] 351 continue 352 353 if "memory_max" in line: 354 memory_max = line.split()[-2] 355 continue 356 357 return safe_cast_int(memory_max), safe_cast_int(memory_median) 358 359 360def get_gpu_time(): 361 # Pull the results from the device and parse 362 result = run_adb_command('shell cat /sdcard/Download/out.txt') 363 gpu_time = '0' 364 365 for line in result.stdout.splitlines(): 366 # Look for "gpu_time" in the line and grab the second to last entry: 367 logging.debug('Checking line: %s' % line) 368 369 if "gpu_time" in line: 370 gpu_time = line.split()[-2] 371 break 372 373 return gpu_time 374 375 376def get_cpu_time(): 377 # Pull the results from the device and parse 378 result = run_adb_command('shell cat /sdcard/Download/out.txt') 379 cpu_time = '0' 380 381 for line in result.stdout.splitlines(): 382 # Look for "cpu_time" in the line and grab the second to last entry: 383 logging.debug('Checking line: %s' % line) 384 385 if "cpu_time" in line: 386 cpu_time = line.split()[-2] 387 break 388 389 return cpu_time 390 391 392def get_frame_count(): 393 # Pull the results from the device and parse 394 result = run_adb_command('shell cat /sdcard/Download/out.txt | grep -v Error | grep -v Frame') 395 396 frame_count = 0 397 398 for line in result.stdout.splitlines(): 399 logging.debug('Checking line: %s' % line) 400 if "trial_steps" in line: 401 frame_count = line.split()[-2] 402 break 403 404 logging.debug('Frame count: %s' % frame_count) 405 return frame_count 406 407 408class GPUPowerStats(): 409 410 # GPU power measured in uWs 411 412 def __init__(self): 413 self.power = {'gpu': 0, 'big_cpu': 0, 'mid_cpu': 0, 'little_cpu': 0} 414 415 def gpu_delta(self, starting): 416 return self.power['gpu'] - starting.power['gpu'] 417 418 def cpu_delta(self, starting): 419 big = self.power['big_cpu'] - starting.power['big_cpu'] 420 mid = self.power['mid_cpu'] - starting.power['mid_cpu'] 421 little = self.power['little_cpu'] - starting.power['little_cpu'] 422 return big + mid + little 423 424 def get_power_data(self): 425 energy_value_result = run_adb_command( 426 'shell cat /sys/bus/iio/devices/iio:device*/energy_value') 427 # Output like this (ordering doesn't matter) 428 # 429 # t=251741617 430 # CH0(T=251741617)[VSYS_PWR_WLAN_BT], 192612469095 431 # CH1(T=251741617)[L2S_VDD_AOC_RET], 1393792850 432 # CH2(T=251741617)[S9S_VDD_AOC], 16816975638 433 # CH3(T=251741617)[S5S_VDDQ_MEM], 2720913855 434 # CH4(T=251741617)[S10S_VDD2L], 3656592412 435 # CH5(T=251741617)[S4S_VDD2H_MEM], 4597271837 436 # CH6(T=251741617)[S2S_VDD_G3D], 3702041607 437 # CH7(T=251741617)[L9S_GNSS_CORE], 88535064 438 # t=16086645 439 # CH0(T=16086645)[PPVAR_VSYS_PWR_DISP], 611687448 440 # CH1(T=16086645)[VSYS_PWR_MODEM], 179646995 441 # CH2(T=16086645)[VSYS_PWR_RFFE], 0 442 # CH3(T=16086645)[S2M_VDD_CPUCL2], 124265856 443 # CH4(T=16086645)[S3M_VDD_CPUCL1], 170096352 444 # CH5(T=16086645)[S4M_VDD_CPUCL0], 289995530 445 # CH6(T=16086645)[S5M_VDD_INT], 190164699 446 # CH7(T=16086645)[S1M_VDD_MIF], 196512891 447 448 id_map = { 449 'S2S_VDD_G3D': 'gpu', 450 'S2M_VDD_CPUCL2': 'big_cpu', 451 'S3M_VDD_CPUCL1': 'mid_cpu', 452 'S4M_VDD_CPUCL0': 'little_cpu', 453 } 454 455 for m in id_map.values(): 456 self.power[m] = 0 # Set to 0 to check for missing values and dupes below 457 458 for line in energy_value_result.stdout.splitlines(): 459 for mid, m in id_map.items(): 460 if mid in line: 461 value = int(line.split()[1]) 462 logging.debug('Power metric %s (%s): %d', mid, m, value) 463 assert self.power[m] == 0, 'Duplicate power metric: %s (%s)' % (mid, m) 464 self.power[m] = value 465 466 for mid, m in id_map.items(): 467 assert self.power[m] != 0, 'Power metric not found: %s (%s)' % (mid, m) 468 469 470def wait_for_test_warmup(done_event): 471 p = subprocess.Popen(['adb', 'logcat', '*:S', 'ANGLE:I'], 472 stdout=subprocess.PIPE, 473 text=True, 474 bufsize=1) # line-buffered 475 os.set_blocking(p.stdout.fileno(), False) 476 477 start_time = time.time() 478 while True: 479 line = p.stdout.readline() # non-blocking as per set_blocking above 480 481 # Look for text logged by the harness when warmup is complete and a test is starting 482 if 'running test name' in line: 483 p.kill() 484 break 485 if done_event.is_set(): 486 logging.warning('Test finished without logging to logcat') 487 p.kill() 488 break 489 490 time.sleep(0.05) 491 492 p.poll() 493 if p.returncode != None: 494 logging.warning('Logcat terminated unexpectedly') 495 return 496 497 498def collect_power(done_event, test_fixedtime, results): 499 # Starting point is post test warmup as there are spikes during warmup 500 wait_for_test_warmup(done_event) 501 502 starting_power = GPUPowerStats() 503 starting_power.get_power_data() 504 logging.debug('Starting power: %s' % starting_power.power) 505 506 duration = test_fixedtime - 1.0 # Avoid measuring through test termination 507 start_time = time.time() 508 while time.time() - start_time < duration: 509 if done_event.is_set(): 510 logging.warning('Test finished earlier than expected by collect_power') 511 break 512 time.sleep(0.05) 513 514 ending_power = GPUPowerStats() 515 ending_power.get_power_data() 516 dt = time.time() - start_time 517 logging.debug('Ending power: %s' % ending_power.power) 518 519 results.update({ 520 # 1e6 for uW -> W 521 'cpu': ending_power.cpu_delta(starting_power) / dt / 1e6, 522 'gpu': ending_power.gpu_delta(starting_power) / dt / 1e6, 523 }) 524 525 526def get_thermal_info(): 527 out = run_adb_command('shell dumpsys android.hardware.thermal.IThermal/default').stdout 528 result = [l for l in out.splitlines() if ('VIRTUAL-SKIN' in l and 'ThrottlingStatus:' in l)] 529 if not result: 530 logging.error('Unexpected dumpsys IThermal response:\n%s', out) 531 raise RuntimeError('Unexpected dumpsys IThermal response, logged above') 532 return result 533 534 535def set_vendor_thermal_control(disabled=None): 536 if disabled: 537 # When disabling, first wait for vendor throttling to end to reset all state 538 waiting = True 539 while waiting: 540 waiting = False 541 for line in get_thermal_info(): 542 is_charge = 'VIRTUAL-SKIN-CHARGE-' in line # Only supposed to affect charging speed 543 if 'ThrottlingStatus: NONE' not in line and not is_charge: 544 logging.info('Waiting for vendor throttling to finish: %s', line.strip()) 545 time.sleep(10) 546 waiting = True 547 break 548 549 run_adb_command('shell setprop persist.vendor.disable.thermal.control %d' % disabled) 550 551 552def sleep_until_temps_below(limit_temp): 553 waiting = True 554 while waiting: 555 waiting = False 556 for line in get_thermal_info(): 557 v = float(line.split('CurrentValue:')[1].strip().split(' ')[0]) 558 if v > limit_temp: 559 logging.info('Waiting for device temps below %.1f: %s', limit_temp, line.strip()) 560 time.sleep(5) 561 waiting = True 562 break 563 564 565def sleep_until_battery_level(min_battery_level): 566 while True: 567 level = int(run_adb_command('shell dumpsys battery get level').stdout.strip()) 568 if level >= min_battery_level: 569 break 570 logging.info('Waiting for device battery level to reach %d. Current level: %d', 571 min_battery_level, level) 572 time.sleep(10) 573 574 575def drop_high_low_and_average(values): 576 if len(values) >= 3: 577 values.remove(min(values)) 578 values.remove(max(values)) 579 580 average = statistics.mean(values) 581 582 variance = 0 583 if len(values) >= 2 and average != 0: 584 variance = statistics.stdev(values) / average 585 586 print(average, variance) 587 588 return float(average), float(variance) 589 590 591def safe_divide(x, y): 592 if y == 0: 593 return 0 594 return x / y 595 596 597def safe_cast_float(x): 598 if x == '': 599 return 0 600 return float(x) 601 602 603def safe_cast_int(x): 604 if x == '': 605 return 0 606 return int(x) 607 608 609def percent(x): 610 return "%.2f%%" % (x * 100) 611 612 613def main(): 614 parser = argparse.ArgumentParser() 615 parser.add_argument('-f', '--filter', help='Trace filter. Defaults to all.', default='*') 616 parser.add_argument('-l', '--log', help='Logging level.', default=DEFAULT_LOG_LEVEL) 617 parser.add_argument( 618 '--renderer', 619 help='Which renderer to use: native, vulkan (via ANGLE), or default (' + 620 'GLES driver selected by system). Providing no option will run twice, native and vulkan', 621 default='both') 622 parser.add_argument( 623 '--walltimeonly', 624 help='Limit output to just wall time', 625 action='store_true', 626 default=False) 627 parser.add_argument( 628 '--power', help='Include CPU/GPU power used per trace', action='store_true', default=False) 629 parser.add_argument( 630 '--memory', 631 help='Include CPU/GPU memory used per trace', 632 action='store_true', 633 default=False) 634 parser.add_argument('--maxsteps', help='Run for fixed set of frames', default='') 635 parser.add_argument('--fixedtime', help='Run for fixed set of time', default='') 636 parser.add_argument( 637 '--minimizegpuwork', 638 help='Whether to run with minimized GPU work', 639 action='store_true', 640 default=False) 641 parser.add_argument('--output-tag', help='Tag for output files.', required=True) 642 parser.add_argument( 643 '--loop-count', help='How many times to loop through the traces', default=5) 644 parser.add_argument( 645 '--device', help='Which device to run the tests on (use serial)', default='') 646 parser.add_argument( 647 '--sleep', help='Add a sleep of this many seconds between each test)', type=int, default=0) 648 parser.add_argument( 649 '--custom-throttling-temp', 650 help='Custom thermal throttling with limit set to this temperature (off by default)', 651 type=float) 652 parser.add_argument( 653 '--min-battery-level', 654 help='Sleep between tests if battery level drops below this value (off by default)', 655 type=int) 656 657 group = parser.add_mutually_exclusive_group() 658 group.add_argument( 659 '--vsync', 660 help='Whether to run the trace in vsync mode', 661 action='store_true', 662 default=False) 663 group.add_argument( 664 '--offscreen', 665 help='Whether to run the trace in offscreen mode', 666 action='store_true', 667 default=False) 668 669 args = parser.parse_args() 670 671 logging.basicConfig(level=args.log.upper()) 672 673 run_adb_command('root') 674 675 try: 676 if args.custom_throttling_temp: 677 set_vendor_thermal_control(disabled=1) 678 run_traces(args) 679 finally: 680 if args.custom_throttling_temp: 681 set_vendor_thermal_control(disabled=0) 682 # Clean up settings, including in case of exceptions (including Ctrl-C) 683 run_adb_command('shell settings delete global angle_debug_package') 684 run_adb_command('shell settings delete global angle_gl_driver_selection_pkgs') 685 run_adb_command('shell settings delete global angle_gl_driver_selection_values') 686 687 return 0 688 689 690def logged_args(): 691 parser = argparse.ArgumentParser() 692 parser.add_argument('--output-tag') 693 _, extra_args = parser.parse_known_args() 694 return ' '.join(extra_args) 695 696 697def run_traces(args): 698 # Load trace names 699 with open(os.path.join(DEFAULT_TEST_DIR, DEFAULT_TEST_JSON)) as f: 700 traces = json.loads(f.read()) 701 702 # Have to split the 'trace version' thing up 703 trace_and_version = traces['traces'] 704 traces = [i.split(' ',)[0] for i in trace_and_version] 705 706 failures = [] 707 708 mode = get_mode(args) 709 trace_width = get_trace_width(mode) 710 711 # Select the target device 712 select_device(args.device) 713 714 # Add an underscore to the mode for use in loop below 715 if mode != '': 716 mode = mode + '_' 717 718 # Create output CSV 719 raw_data_filename = "raw_data." + args.output_tag + ".csv" 720 output_file = open(raw_data_filename, 'w', newline='') 721 output_writer = csv.writer(output_file) 722 723 # Set some widths that allow easily reading the values, but fit on smaller monitors. 724 column_width = { 725 'trace': trace_width, 726 'wall_time': 15, 727 'gpu_time': 15, 728 'cpu_time': 15, 729 'gpu_power': 10, 730 'cpu_power': 10, 731 'gpu_mem_sustained': 20, 732 'gpu_mem_peak': 15, 733 'proc_mem_median': 20, 734 'proc_mem_peak': 15 735 } 736 737 if args.walltimeonly: 738 print('%-*s' % (trace_width, 'wall_time_per_frame')) 739 else: 740 print('%-*s %-*s %-*s %-*s %-*s %-*s %-*s %-*s %-*s %-*s' % 741 (column_width['trace'], 'trace', column_width['wall_time'], 'wall_time', 742 column_width['gpu_time'], 'gpu_time', column_width['cpu_time'], 'cpu_time', 743 column_width['gpu_power'], 'gpu_power', column_width['cpu_power'], 'cpu_power', 744 column_width['gpu_mem_sustained'], 'gpu_mem_sustained', 745 column_width['gpu_mem_peak'], 'gpu_mem_peak', column_width['proc_mem_median'], 746 'proc_mem_median', column_width['proc_mem_peak'], 'proc_mem_peak')) 747 output_writer.writerow([ 748 'trace', 'wall_time(ms)', 'gpu_time(ms)', 'cpu_time(ms)', 'gpu_power(W)', 749 'cpu_power(W)', 'gpu_mem_sustained', 'gpu_mem_peak', 'proc_mem_median', 'proc_mem_peak' 750 ]) 751 752 if args.power: 753 starting_power = GPUPowerStats() 754 ending_power = GPUPowerStats() 755 756 renderers = [] 757 if args.renderer != "both": 758 renderers.append(args.renderer) 759 else: 760 renderers = ("native", "vulkan") 761 762 wall_times = defaultdict(dict) 763 gpu_times = defaultdict(dict) 764 cpu_times = defaultdict(dict) 765 gpu_powers = defaultdict(dict) 766 cpu_powers = defaultdict(dict) 767 gpu_mem_sustaineds = defaultdict(dict) 768 gpu_mem_peaks = defaultdict(dict) 769 proc_mem_medians = defaultdict(dict) 770 proc_mem_peaks = defaultdict(dict) 771 772 for renderer in renderers: 773 774 if renderer == "native": 775 # Force the settings to native 776 run_adb_command('shell settings put global angle_debug_package org.chromium.angle') 777 run_adb_command( 778 'shell settings put global angle_gl_driver_selection_pkgs com.android.angle.test') 779 run_adb_command('shell settings put global angle_gl_driver_selection_values native') 780 elif renderer == "vulkan": 781 # Force the settings to ANGLE 782 run_adb_command('shell settings put global angle_debug_package org.chromium.angle') 783 run_adb_command( 784 'shell settings put global angle_gl_driver_selection_pkgs com.android.angle.test') 785 run_adb_command('shell settings put global angle_gl_driver_selection_values angle') 786 elif renderer == "default": 787 logging.info('Deleting Android settings for forcing selection of GLES driver, ' + 788 'allowing system to load the default') 789 run_adb_command('shell settings delete global angle_debug_package') 790 run_adb_command('shell settings delete global angle_gl_driver_selection_pkgs') 791 run_adb_command('shell settings delete global angle_gl_driver_selection_values') 792 else: 793 logging.error('Unsupported renderer {}'.format(renderer)) 794 exit() 795 796 for i in range(int(args.loop_count)): 797 print("\nStarting run %i with %s at %s\n" % 798 (i + 1, renderer, datetime.now().strftime('%Y-%m-%d %H:%M:%S'))) 799 for trace in fnmatch.filter(traces, args.filter): 800 # Remove any previous perf results 801 cleanup() 802 # Clear blob cache to avoid post-warmup cache eviction b/298028816 803 clear_blob_cache() 804 805 test = trace.split(' ')[0] 806 807 if args.power: 808 assert args.fixedtime, '--power requires --fixedtime' 809 done_event = threading.Event() 810 run_adb_command('logcat -c') # needed for wait_for_test_warmup 811 power_results = {} # output arg 812 power_thread = threading.Thread( 813 target=collect_power, 814 args=(done_event, float(args.fixedtime), power_results)) 815 power_thread.daemon = True 816 power_thread.start() 817 818 logging.debug('Running %s' % test) 819 test_time = run_trace(test, args) 820 821 gpu_power, cpu_power = 0, 0 822 if args.power: 823 done_event.set() 824 power_thread.join(timeout=2) 825 if power_thread.is_alive(): 826 logging.warning('collect_power thread did not terminate') 827 else: 828 gpu_power = power_results['gpu'] 829 cpu_power = power_results['cpu'] 830 831 wall_time = get_test_time() 832 833 gpu_time = get_gpu_time() if args.vsync else '0' 834 835 cpu_time = get_cpu_time() 836 837 gpu_mem_sustained, gpu_mem_peak = 0, 0 838 proc_mem_peak, proc_mem_median = 0, 0 839 if args.memory: 840 gpu_mem_sustained, gpu_mem_peak = get_gpu_memory(test_time) 841 logging.debug( 842 '%s = %i, %s = %i' % 843 ('gpu_mem_sustained', gpu_mem_sustained, 'gpu_mem_peak', gpu_mem_peak)) 844 845 proc_mem_peak, proc_mem_median = get_proc_memory() 846 847 trace_name = mode + renderer + '_' + test 848 849 if len(wall_times[test]) == 0: 850 wall_times[test] = defaultdict(list) 851 try: 852 wt = safe_cast_float(wall_time) 853 except ValueError: # e.g. 'crashed' 854 wt = -1 855 wall_times[test][renderer].append(wt) 856 857 if len(gpu_times[test]) == 0: 858 gpu_times[test] = defaultdict(list) 859 gpu_times[test][renderer].append(safe_cast_float(gpu_time)) 860 861 if len(cpu_times[test]) == 0: 862 cpu_times[test] = defaultdict(list) 863 cpu_times[test][renderer].append(safe_cast_float(cpu_time)) 864 865 if len(gpu_powers[test]) == 0: 866 gpu_powers[test] = defaultdict(list) 867 gpu_powers[test][renderer].append(safe_cast_float(gpu_power)) 868 869 if len(cpu_powers[test]) == 0: 870 cpu_powers[test] = defaultdict(list) 871 cpu_powers[test][renderer].append(safe_cast_float(cpu_power)) 872 873 if len(gpu_mem_sustaineds[test]) == 0: 874 gpu_mem_sustaineds[test] = defaultdict(list) 875 gpu_mem_sustaineds[test][renderer].append(safe_cast_int(gpu_mem_sustained)) 876 877 if len(gpu_mem_peaks[test]) == 0: 878 gpu_mem_peaks[test] = defaultdict(list) 879 gpu_mem_peaks[test][renderer].append(safe_cast_int(gpu_mem_peak)) 880 881 if len(proc_mem_medians[test]) == 0: 882 proc_mem_medians[test] = defaultdict(list) 883 proc_mem_medians[test][renderer].append(safe_cast_int(proc_mem_median)) 884 885 if len(proc_mem_peaks[test]) == 0: 886 proc_mem_peaks[test] = defaultdict(list) 887 proc_mem_peaks[test][renderer].append(safe_cast_int(proc_mem_peak)) 888 889 if args.walltimeonly: 890 print('%-*s' % (trace_width, wall_time)) 891 else: 892 print( 893 '%-*s %-*s %-*s %-*s %-*s %-*s %-*i %-*i %-*i %-*i' % 894 (column_width['trace'], trace_name, column_width['wall_time'], wall_time, 895 column_width['gpu_time'], gpu_time, column_width['cpu_time'], cpu_time, 896 column_width['gpu_power'], '%.3f' % gpu_power, column_width['cpu_power'], 897 '%.3f' % cpu_power, column_width['gpu_mem_sustained'], gpu_mem_sustained, 898 column_width['gpu_mem_peak'], gpu_mem_peak, 899 column_width['proc_mem_median'], proc_mem_median, 900 column_width['proc_mem_peak'], proc_mem_peak)) 901 output_writer.writerow([ 902 mode + renderer + '_' + test, wall_time, gpu_time, cpu_time, gpu_power, 903 cpu_power, gpu_mem_sustained, gpu_mem_peak, proc_mem_median, proc_mem_peak 904 ]) 905 906 907 # Early exit for testing 908 #exit() 909 910 # Depending on workload, sleeps might be needed to dissipate heat or recharge battery 911 if args.sleep != 0: 912 time.sleep(args.sleep) 913 914 if args.custom_throttling_temp: 915 sleep_until_temps_below(args.custom_throttling_temp) 916 917 if args.min_battery_level: 918 sleep_until_battery_level(args.min_battery_level) 919 920 # Organize the data for writing out 921 rows = defaultdict(dict) 922 923 def populate_row(rows, name, results): 924 if len(rows[name]) == 0: 925 rows[name] = defaultdict(list) 926 for renderer, wtimes in results.items(): 927 average, variance = drop_high_low_and_average(wtimes) 928 rows[name][renderer].append(average) 929 rows[name][renderer].append(variance) 930 931 for name, results in wall_times.items(): 932 populate_row(rows, name, results) 933 934 for name, results in gpu_times.items(): 935 populate_row(rows, name, results) 936 937 for name, results in cpu_times.items(): 938 populate_row(rows, name, results) 939 940 for name, results in gpu_powers.items(): 941 populate_row(rows, name, results) 942 943 for name, results in cpu_powers.items(): 944 populate_row(rows, name, results) 945 946 for name, results in gpu_mem_sustaineds.items(): 947 populate_row(rows, name, results) 948 949 for name, results in gpu_mem_peaks.items(): 950 populate_row(rows, name, results) 951 952 for name, results in proc_mem_medians.items(): 953 populate_row(rows, name, results) 954 955 for name, results in proc_mem_peaks.items(): 956 populate_row(rows, name, results) 957 958 # Generate the SUMMARY output 959 summary_file = open("summary." + args.output_tag + ".csv", 'w', newline='') 960 summary_writer = csv.writer(summary_file) 961 962 android_version = run_adb_command('shell getprop ro.build.fingerprint').stdout.strip() 963 angle_version = run_command('git rev-parse HEAD').stdout.strip() 964 # test_time = run_command('date \"+%Y%m%d\"').stdout.read().strip() 965 966 summary_writer.writerow([ 967 "\"Android: " + android_version + "\n" + "ANGLE: " + angle_version + "\n" + 968 # "Date: " + test_time + "\n" + 969 "Source: " + raw_data_filename + "\n" + "Args: " + logged_args() + "\"" 970 ]) 971 972 # Write the summary file 973 trace_number = 0 974 975 if (len(renderers) == 1) and (renderers[0] != "both"): 976 renderer_name = renderers[0] 977 summary_writer.writerow([ 978 "#", "\"Trace\"", f"\"{renderer_name}\nwall\ntime\nper\nframe\n(ms)\"", 979 f"\"{renderer_name}\nwall\ntime\nvariance\"", 980 f"\"{renderer_name}\nGPU\ntime\nper\nframe\n(ms)\"", 981 f"\"{renderer_name}\nGPU\ntime\nvariance\"", 982 f"\"{renderer_name}\nCPU\ntime\nper\nframe\n(ms)\"", 983 f"\"{renderer_name}\nCPU\ntime\nvariance\"", f"\"{renderer_name}\nGPU\npower\n(W)\"", 984 f"\"{renderer_name}\nGPU\npower\nvariance\"", f"\"{renderer_name}\nCPU\npower\n(W)\"", 985 f"\"{renderer_name}\nCPU\npower\nvariance\"", f"\"{renderer_name}\nGPU\nmem\n(B)\"", 986 f"\"{renderer_name}\nGPU\nmem\nvariance\"", 987 f"\"{renderer_name}\npeak\nGPU\nmem\n(B)\"", 988 f"\"{renderer_name}\npeak\nGPU\nmem\nvariance\"", 989 f"\"{renderer_name}\nprocess\nmem\n(B)\"", 990 f"\"{renderer_name}\nprocess\nmem\nvariance\"", 991 f"\"{renderer_name}\npeak\nprocess\nmem\n(B)\"", 992 f"\"{renderer_name}\npeak\nprocess\nmem\nvariance\"" 993 ]) 994 995 for name, data in rows.items(): 996 trace_number += 1 997 summary_writer.writerow([ 998 trace_number, 999 name, 1000 # wall_time 1001 "%.3f" % data[renderer_name][0], 1002 percent(data[renderer_name][1]), 1003 # GPU time 1004 "%.3f" % data[renderer_name][2], 1005 percent(data[renderer_name][3]), 1006 # CPU time 1007 "%.3f" % data[renderer_name][4], 1008 percent(data[renderer_name][5]), 1009 # GPU power 1010 "%.3f" % data[renderer_name][6], 1011 percent(data[renderer_name][7]), 1012 # CPU power 1013 "%.3f" % data[renderer_name][8], 1014 percent(data[renderer_name][9]), 1015 # GPU mem 1016 int(data[renderer_name][10]), 1017 percent(data[renderer_name][11]), 1018 # GPU peak mem 1019 int(data[renderer_name][12]), 1020 percent(data[renderer_name][13]), 1021 # process mem 1022 int(data[renderer_name][14]), 1023 percent(data[renderer_name][15]), 1024 # process peak mem 1025 int(data[renderer_name][16]), 1026 percent(data[renderer_name][17]), 1027 ]) 1028 else: 1029 summary_writer.writerow([ 1030 "#", "\"Trace\"", "\"Native\nwall\ntime\nper\nframe\n(ms)\"", 1031 "\"Native\nwall\ntime\nvariance\"", "\"ANGLE\nwall\ntime\nper\nframe\n(ms)\"", 1032 "\"ANGLE\nwall\ntime\nvariance\"", "\"wall\ntime\ncompare\"", 1033 "\"Native\nGPU\ntime\nper\nframe\n(ms)\"", "\"Native\nGPU\ntime\nvariance\"", 1034 "\"ANGLE\nGPU\ntime\nper\nframe\n(ms)\"", "\"ANGLE\nGPU\ntime\nvariance\"", 1035 "\"GPU\ntime\ncompare\"", "\"Native\nCPU\ntime\nper\nframe\n(ms)\"", 1036 "\"Native\nCPU\ntime\nvariance\"", "\"ANGLE\nCPU\ntime\nper\nframe\n(ms)\"", 1037 "\"ANGLE\nCPU\ntime\nvariance\"", "\"CPU\ntime\ncompare\"", 1038 "\"Native\nGPU\npower\n(W)\"", "\"Native\nGPU\npower\nvariance\"", 1039 "\"ANGLE\nGPU\npower\n(W)\"", "\"ANGLE\nGPU\npower\nvariance\"", 1040 "\"GPU\npower\ncompare\"", "\"Native\nCPU\npower\n(W)\"", 1041 "\"Native\nCPU\npower\nvariance\"", "\"ANGLE\nCPU\npower\n(W)\"", 1042 "\"ANGLE\nCPU\npower\nvariance\"", "\"CPU\npower\ncompare\"", 1043 "\"Native\nGPU\nmem\n(B)\"", "\"Native\nGPU\nmem\nvariance\"", 1044 "\"ANGLE\nGPU\nmem\n(B)\"", "\"ANGLE\nGPU\nmem\nvariance\"", "\"GPU\nmem\ncompare\"", 1045 "\"Native\npeak\nGPU\nmem\n(B)\"", "\"Native\npeak\nGPU\nmem\nvariance\"", 1046 "\"ANGLE\npeak\nGPU\nmem\n(B)\"", "\"ANGLE\npeak\nGPU\nmem\nvariance\"", 1047 "\"GPU\npeak\nmem\ncompare\"", "\"Native\nprocess\nmem\n(B)\"", 1048 "\"Native\nprocess\nmem\nvariance\"", "\"ANGLE\nprocess\nmem\n(B)\"", 1049 "\"ANGLE\nprocess\nmem\nvariance\"", "\"process\nmem\ncompare\"", 1050 "\"Native\npeak\nprocess\nmem\n(B)\"", "\"Native\npeak\nprocess\nmem\nvariance\"", 1051 "\"ANGLE\npeak\nprocess\nmem\n(B)\"", "\"ANGLE\npeak\nprocess\nmem\nvariance\"", 1052 "\"process\npeak\nmem\ncompare\"" 1053 ]) 1054 1055 for name, data in rows.items(): 1056 trace_number += 1 1057 summary_writer.writerow([ 1058 trace_number, 1059 name, 1060 # wall_time 1061 "%.3f" % data["native"][0], 1062 percent(data["native"][1]), 1063 "%.3f" % data["vulkan"][0], 1064 percent(data["vulkan"][1]), 1065 percent(safe_divide(data["native"][0], data["vulkan"][0])), 1066 # GPU time 1067 "%.3f" % data["native"][2], 1068 percent(data["native"][3]), 1069 "%.3f" % data["vulkan"][2], 1070 percent(data["vulkan"][3]), 1071 percent(safe_divide(data["native"][2], data["vulkan"][2])), 1072 # CPU time 1073 "%.3f" % data["native"][4], 1074 percent(data["native"][5]), 1075 "%.3f" % data["vulkan"][4], 1076 percent(data["vulkan"][5]), 1077 percent(safe_divide(data["native"][4], data["vulkan"][4])), 1078 # GPU power 1079 "%.3f" % data["native"][6], 1080 percent(data["native"][7]), 1081 "%.3f" % data["vulkan"][6], 1082 percent(data["vulkan"][7]), 1083 percent(safe_divide(data["native"][6], data["vulkan"][6])), 1084 # CPU power 1085 "%.3f" % data["native"][8], 1086 percent(data["native"][9]), 1087 "%.3f" % data["vulkan"][8], 1088 percent(data["vulkan"][9]), 1089 percent(safe_divide(data["native"][8], data["vulkan"][8])), 1090 # GPU mem 1091 int(data["native"][10]), 1092 percent(data["native"][11]), 1093 int(data["vulkan"][10]), 1094 percent(data["vulkan"][11]), 1095 percent(safe_divide(data["native"][10], data["vulkan"][10])), 1096 # GPU peak mem 1097 int(data["native"][12]), 1098 percent(data["native"][13]), 1099 int(data["vulkan"][12]), 1100 percent(data["vulkan"][13]), 1101 percent(safe_divide(data["native"][12], data["vulkan"][12])), 1102 # process mem 1103 int(data["native"][14]), 1104 percent(data["native"][15]), 1105 int(data["vulkan"][14]), 1106 percent(data["vulkan"][15]), 1107 percent(safe_divide(data["native"][14], data["vulkan"][14])), 1108 # process peak mem 1109 int(data["native"][16]), 1110 percent(data["native"][17]), 1111 int(data["vulkan"][16]), 1112 percent(data["vulkan"][17]), 1113 percent(safe_divide(data["native"][16], data["vulkan"][16])) 1114 ]) 1115 1116 1117if __name__ == '__main__': 1118 sys.exit(main()) 1119