| #!/usr/bin/env python |
| """Performance test to compare the performance of buck between two revisions. |
| |
| The general algorithm is: |
| |
| Checkout <revisions_to_go_back - 1> |
| Warm up the cache: |
| Set .buckversion to old revision, build all targets |
| Set .buckversion to new revision, build all targets |
| |
| For each revision to test: |
| - Rename directory being tested |
| - Build all targets, check to ensure everything pulls from dir cache |
| - Check out revision to test |
| - Clean Build all targets <iterations_per_diff> times, only reading from |
| cache, not writing (except for the last one, write that time) |
| - Buck build all targets to verify no-op build works. |
| |
| """ |
| import argparse |
| import re |
| import subprocess |
| import os |
| import tempfile |
| import sys |
| |
| from collections import defaultdict |
| from datetime import datetime |
| |
| |
| def createArgParser(): |
| parser = argparse.ArgumentParser( |
| description='Run the buck performance test') |
| parser.add_argument( |
| '--perftest_id', |
| action='store', |
| type=str, |
| help='The identifier of this performance test') |
| parser.add_argument( |
| '--revisions_to_go_back', |
| action='store', |
| type=int, |
| help='The maximum number of revisions to go back when testing') |
| parser.add_argument( |
| '--iterations_per_diff', |
| action='store', |
| type=int, |
| help='The number of iterations to run on diff') |
| parser.add_argument( |
| '--targets_to_build', |
| action='append', |
| type=str, |
| help='The targets to build') |
| parser.add_argument( |
| '--repo_under_test', |
| action='store', |
| type=str, |
| help='Path to the repo under test') |
| parser.add_argument( |
| '--path_to_buck', |
| action='store', |
| type=str, |
| help='The path to the buck binary') |
| parser.add_argument( |
| '--old_buck_revision', |
| action='store', |
| type=str, |
| help='The original buck revision') |
| parser.add_argument( |
| '--new_buck_revision', |
| action='store', |
| type=str, |
| help='The new buck revision') |
| return parser |
| |
| |
| def log(message): |
| print '%s\t%s' % (str(datetime.now()), message) |
| sys.stdout.flush() |
| |
| |
| class BuildResult(): |
| def __init__(self, time_delta, cache_results, rule_key_map): |
| self.time_delta = time_delta |
| self.cache_results = cache_results |
| self.rule_key_map = rule_key_map |
| |
| |
| def git_clean(cwd): |
| log('Running git clean.') |
| subprocess.check_call( |
| ['git', 'clean', '--quiet', '-xfd'], |
| cwd=cwd) |
| |
| |
| def git_reset(cwd, revision): |
| subprocess.check_call( |
| ['git', 'reset', '--quiet', '--hard', revision], |
| cwd=cwd) |
| |
| |
| def buck_clean(args, cwd): |
| log('Running buck clean.') |
| subprocess.check_call( |
| [args.path_to_buck, 'clean'], |
| cwd=cwd) |
| |
| |
| def git_get_revisions(args): |
| return list(reversed(subprocess.check_output( |
| ['git', 'log', '--pretty=format:%H', 'HEAD', '-n', |
| str(args.revisions_to_go_back + 1)], |
| cwd=args.repo_under_test).splitlines())) |
| |
| |
| def git_checkout(revision, cwd): |
| log('Checking out %s.' % revision) |
| git_reset(cwd, 'HEAD') |
| subprocess.check_call( |
| ['git', 'checkout', '--quiet', revision], |
| cwd=cwd) |
| |
| |
| BUILD_RESULT_LOG_LINE = re.compile( |
| r'BuildRuleFinished\((?P<rule_name>[\w_\-:#\/]+)\): (?P<result>[A-Z_]+) ' |
| r'(?P<cache_result>[A-Z_]+) (?P<success_type>[A-Z_]+) ' |
| r'(?P<rule_key>[0-9a-f]*)') |
| |
| |
| RULEKEY_LINE = re.compile( |
| r'^INFO: RuleKey (?P<rule_key>[0-9a-f]*)=' |
| r'(?P<rule_key_debug>.*)$') |
| |
| |
| BUCK_LOG_RULEKEY_LINE = re.compile( |
| r'.*\[\w+\](?:\[command:[0-9a-f-]+\])?\[tid:\d+\]' |
| r'\[com.facebook.buck.rules.RuleKey[\$\.]Builder\] ' |
| r'RuleKey (?P<rule_key>[0-9a-f]+)=' |
| r'(?P<rule_key_debug>.*)$') |
| |
| |
| def buck_build_target(args, cwd, target, perftest_side, log_as_perftest=True): |
| """Builds a target with buck and returns performance information. |
| """ |
| log('Running buck build %s.' % target) |
| bucklogging_properties_path = os.path.join( |
| cwd, '.bucklogging.local.properties') |
| with open(bucklogging_properties_path, 'w') as bucklogging_properties: |
| # The default configuration has the root logger and FileHandler |
| # discard anything below FINE level. |
| # |
| # We need RuleKey logging, which uses FINER (verbose), so the |
| # root logger and file handler both need to be reconfigured |
| # to enable verbose logging. |
| bucklogging_properties.write( |
| '''.level=FINER |
| java.util.logging.FileHandler.level=FINER''') |
| env = os.environ.copy() |
| # Force buck to pretend it's repo is clean. |
| env.update({ |
| 'BUCK_REPOSITORY_DIRTY': '0' |
| }) |
| if log_as_perftest: |
| env.update({ |
| 'BUCK_EXTRA_JAVA_ARGS': |
| '-Dbuck.perftest_id=%s, -Dbuck.perftest_side=%s' % ( |
| args.perftest_id, perftest_side) |
| }) |
| start = datetime.now() |
| with tempfile.TemporaryFile() as tmpFile: |
| try: |
| subprocess.check_call( |
| [args.path_to_buck, 'build', target, '-v', '5'], |
| stdout=tmpFile, |
| stderr=tmpFile, |
| cwd=cwd, |
| env=env) |
| except: |
| tmpFile.seek(0) |
| log('Buck build failed: %s' % tmpFile.read()) |
| raise |
| tmpFile.seek(0) |
| build_output = tmpFile.read() |
| finish = datetime.now() |
| |
| java_utils_log_path = os.path.join( |
| cwd, |
| 'buck-out', 'log', 'buck-0.log') |
| if os.path.exists(java_utils_log_path): |
| pattern = BUCK_LOG_RULEKEY_LINE |
| with open(java_utils_log_path) as f: |
| build_output = f.read() |
| else: |
| pattern = RULEKEY_LINE |
| |
| rule_debug_map = {} |
| for line in build_output.splitlines(): |
| match = pattern.match(line) |
| if match: |
| rule_debug_map[match.group('rule_key')] = match.group( |
| 'rule_key_debug') |
| |
| logfile_path = os.path.join( |
| cwd, |
| 'buck-out', 'bin', 'build.log') |
| cache_results = defaultdict(list) |
| rule_key_map = {} |
| with open(logfile_path, 'r') as logfile: |
| for line in logfile.readlines(): |
| line = line.strip() |
| match = BUILD_RESULT_LOG_LINE.search(line) |
| if match: |
| rule_name = match.group('rule_name') |
| rule_key = match.group('rule_key') |
| if not rule_key in rule_debug_map: |
| raise Exception('''ERROR: build.log contains an entry |
| which was not found in buck build -v 5 output. |
| Rule: {}, rule key: {}'''.format(rule_name, rule_key)) |
| cache_results[match.group('cache_result')].append({ |
| 'rule_name': rule_name, |
| 'rule_key': rule_key, |
| 'rule_key_debug': rule_debug_map[rule_key] |
| }) |
| rule_key_map[match.group('rule_name')] = rule_debug_map[ |
| match.group('rule_key')] |
| |
| result = BuildResult(finish - start, cache_results, rule_key_map) |
| cache_counts = {} |
| for key, value in result.cache_results.iteritems(): |
| cache_counts[key] = len(value) |
| log('Test Build Finished! Elapsed Seconds: %d, Cache Counts: %s' % ( |
| result.time_delta.total_seconds(), repr(cache_counts))) |
| return result |
| |
| |
| def set_perftest_side( |
| args, |
| cwd, |
| perftest_side, |
| cache_mode, |
| dir_cache_only=True): |
| log('Reconfiguring to test %s version of buck.' % perftest_side) |
| buckconfig_path = os.path.join(cwd, '.buckconfig.local') |
| with open(buckconfig_path, 'w') as buckconfig: |
| buckconfig.write('''[cache] |
| %s |
| dir = buck-cache-%s |
| dir_mode = %s |
| ''' % ('mode = dir' if dir_cache_only else '', perftest_side, cache_mode)) |
| buckconfig.truncate() |
| buckversion_path = os.path.join(cwd, '.buckversion') |
| with open(buckversion_path, 'w') as buckversion: |
| if perftest_side == 'old': |
| buckversion.write(args.old_buck_revision + os.linesep) |
| else: |
| buckversion.write(args.new_buck_revision + os.linesep) |
| buckversion.truncate() |
| |
| def build_all_targets( |
| args, |
| cwd, |
| perftest_side, |
| cache_mode, |
| run_clean=True, |
| dir_cache_only=True, |
| log_as_perftest=True): |
| set_perftest_side( |
| args, |
| cwd, |
| perftest_side, |
| cache_mode, |
| dir_cache_only=dir_cache_only) |
| result = {} |
| for target in args.targets_to_build: |
| if run_clean: |
| buck_clean(args, cwd) |
| #TODO(royw): Do smart things with the results here. |
| result[target] = buck_build_target( |
| args, |
| cwd, |
| target, |
| perftest_side, |
| log_as_perftest=log_as_perftest) |
| return result |
| |
| |
| def run_tests_for_diff(args, revisions_to_test, test_index, last_results): |
| log('=== Running tests at revision %s ===' % revisions_to_test[test_index]) |
| new_directory_name = (os.path.basename(args.repo_under_test) + |
| '_test_iteration_%d' % test_index) |
| |
| # Rename the directory to flesh out any cache problems. |
| cwd = os.path.join(os.path.dirname(args.repo_under_test), |
| new_directory_name) |
| log('Renaming %s to %s' % (args.repo_under_test, cwd)) |
| os.rename(args.repo_under_test, cwd) |
| |
| try: |
| log('== Checking new revision for problems with absolute paths ==') |
| results = build_all_targets(args, cwd, 'new', 'readonly') |
| for target, result in results.iteritems(): |
| if (len(result.cache_results.keys()) != 1 or |
| 'DIR_HIT' not in result.cache_results): |
| # Remove DIR_HITs to make error message cleaner |
| result.cache_results.pop('DIR_HIT', None) |
| log('Building %s at revision %s with the new buck version ' |
| 'was unable to reuse the cache from a previous run. ' |
| 'This suggests one of the rule keys contains an ' |
| 'abosolute path.' % ( |
| target, |
| revisions_to_test[test_index - 1])) |
| for rule in result.cache_results['MISS']: |
| rule_name = rule['rule_name'] |
| old_key = last_results[target].rule_key_map[rule_name] |
| log('Rule %s missed.' % rule_name) |
| log('\tOld Rule Key: %s.' % old_key) |
| log('\tNew Rule Key: %s.' % result.rule_key_map[rule_name]) |
| raise Exception('Failed to reuse cache across directories!!!') |
| |
| git_checkout(revisions_to_test[test_index], cwd) |
| |
| for attempt in xrange(args.iterations_per_diff): |
| cache_mode = 'readonly' |
| if attempt == args.iterations_per_diff - 1: |
| cache_mode = 'readwrite' |
| |
| build_all_targets(args, cwd, 'old', cache_mode) |
| build_all_targets(args, cwd, 'new', cache_mode) |
| |
| log('== Checking new revision to ensure noop build does nothing. ==') |
| results = build_all_targets( |
| args, |
| cwd, |
| 'new', |
| cache_mode, |
| run_clean=False) |
| for target, result in results.iteritems(): |
| if (len(result.cache_results.keys()) != 1 or |
| 'LOCAL_KEY_UNCHANGED_HIT' not in result.cache_results): |
| result.cache_results.pop('DIR_HIT', None) |
| raise Exception( |
| 'Doing a noop build for %s at revision %s with the new ' |
| 'buck version did not hit all of it\'s keys.\nMissed ' |
| 'Rules: %s' % ( |
| target, |
| revisions_to_test[test_index - 1], |
| repr(result.cache_results))) |
| |
| finally: |
| log('Renaming %s to %s' % (cwd, args.repo_under_test)) |
| os.rename(cwd, args.repo_under_test) |
| |
| return results |
| |
| |
| def main(): |
| args = createArgParser().parse_args() |
| log('Running Performance Test!') |
| git_clean(args.repo_under_test) |
| revisions_to_test = git_get_revisions(args) |
| # Checkout the revision previous to the test and warm up the local dir |
| # cache. |
| # git_clean(args.repo_under_test) |
| log('=== Warming up cache ===') |
| git_checkout(revisions_to_test[0], args.repo_under_test) |
| build_all_targets( |
| args, |
| args.repo_under_test, |
| 'old', |
| 'readwrite', |
| dir_cache_only=False, |
| log_as_perftest=False) |
| results_for_new = build_all_targets( |
| args, |
| args.repo_under_test, |
| 'new', |
| 'readwrite', |
| dir_cache_only=False, |
| log_as_perftest=False) |
| log('=== Cache Warm! Running tests ===') |
| for i in xrange(1, args.revisions_to_go_back): |
| results_for_new = run_tests_for_diff( |
| args, |
| revisions_to_test, |
| i, |
| results_for_new) |
| |
| |
| if __name__ == '__main__': |
| main() |
