#!/usr/bin/env python2 # -*- coding: utf-8 -*- # Copyright 2019 The Chromium OS Authors. All rights reserved. # Use of this source code is governed by a BSD-style license that can be # found in the LICENSE file. """AFDO Profile analysis tool. This script takes a good AFDO profile, a bad AFDO profile, and an external script which deems particular AFDO profiles as GOOD/BAD/SKIP, and an output file as arguments. Given these pieces of information, it analyzes the profiles to try and determine what exactly is bad about the bad profile. It does this with three main techniques: bisecting search, range search, and rough diff-ing. The external script communicates the 'goodness' of an AFDO profile through its exit code. The codes known to this script are: - 0: the AFDO profile produced a good binary - 1: the AFDO profile produced a bad binary - 125: no result could be determined; just try another profile - >127: quit immediately """ from __future__ import division, print_function import argparse import json # Pylint recommends we use "from chromite.lib import cros_logging as logging". # Chromite specific policy message, we want to keep using the standard logging # pylint: disable=cros-logging-import import logging import os import random import subprocess import time from datetime import date from enum import IntEnum from tempfile import mkstemp class StatusEnum(IntEnum): """Enum of valid statuses returned by profile decider.""" GOOD_STATUS = 0 BAD_STATUS = 1 SKIP_STATUS = 125 PROBLEM_STATUS = 127 statuses = StatusEnum.__members__.values() _NUM_RUNS_RANGE_SEARCH = 20 # how many times range search should run its algo def json_to_text(json_prof): text_profile = [] for func in json_prof: text_profile.append(func) text_profile.append(json_prof[func]) return ''.join(text_profile) def text_to_json(f): """Performs basic parsing of an AFDO text-based profile. This parsing expects an input file object with contents of the form generated by bin/llvm-profdata (within an LLVM build). """ results = {} curr_func = None curr_data = [] for line in f: if not line.startswith(' '): if curr_func: results[curr_func] = ''.join(curr_data) curr_data = [] curr_func, rest = line.split(':', 1) curr_func = curr_func.strip() curr_data.append(':' + rest) else: curr_data.append(line) if curr_func: results[curr_func] = ''.join(curr_data) return results def prof_to_tmp(prof): """Creates (and returns) temp filename for given JSON-based AFDO profile.""" fd, temp_path = mkstemp() text_profile = json_to_text(prof) with open(temp_path, 'w') as f: f.write(text_profile) os.close(fd) return temp_path class DeciderState(object): """Class for the external decider.""" def __init__(self, state_file, external_decider, seed): self.accumulated_results = [] # over this run of the script self.external_decider = external_decider self.saved_results = [] # imported from a previous run of this script self.state_file = state_file self.seed = seed if seed is not None else time.time() def load_state(self): if not os.path.exists(self.state_file): logging.info('State file %s is empty, starting from beginning', self.state_file) return with open(self.state_file) as f: try: data = json.load(f) except: raise ValueError('Provided state file %s to resume from does not' ' contain a valid JSON.' % self.state_file) if 'seed' not in data or 'accumulated_results' not in data: raise ValueError('Provided state file %s to resume from does not contain' ' the correct information' % self.state_file) self.seed = data['seed'] self.saved_results = data['accumulated_results'] logging.info('Restored state from %s...', self.state_file) def save_state(self): state = {'seed': self.seed, 'accumulated_results': self.accumulated_results} tmp_file = self.state_file + '.new' with open(tmp_file, 'w') as f: json.dump(state, f, indent=2) os.rename(tmp_file, self.state_file) logging.info('Logged state to %s...', self.state_file) def run(self, prof, save_run=True): """Run the external deciding script on the given profile.""" if self.saved_results and save_run: result = self.saved_results.pop(0) self.accumulated_results.append(result) self.save_state() return StatusEnum(result) filename = prof_to_tmp(prof) try: return_code = subprocess.call([self.external_decider, filename]) finally: os.remove(filename) if return_code in statuses: status = StatusEnum(return_code) if status == StatusEnum.PROBLEM_STATUS: prof_file = prof_to_tmp(prof) raise RuntimeError('Provided decider script returned PROBLEM_STATUS ' 'when run on profile stored at %s. AFDO Profile ' 'analysis aborting' % prof_file) if save_run: self.accumulated_results.append(status.value) logging.info('Run %d of external script %s returned %s', len(self.accumulated_results), self.external_decider, status.name) self.save_state() return status raise ValueError( 'Provided external script had unexpected return code %d' % return_code) def bisect_profiles(decider, good, bad, common_funcs, lo, hi): """Recursive function which bisects good and bad profiles. Args: decider: function which, given a JSON-based AFDO profile, returns an element of 'statuses' based on the status of the profile good: JSON-based good AFDO profile bad: JSON-based bad AFDO profile common_funcs: the list of functions which have top-level profiles in both 'good' and 'bad' lo: lower bound of range being bisected on hi: upper bound of range being bisected on Returns a dictionary with two keys: 'individuals' and 'ranges'. 'individuals': a list of individual functions found to make the profile BAD 'ranges': a list of lists of function names. Each list of functions is a list such that including all of those from the bad profile makes the good profile BAD. It may not be the smallest problematic combination, but definitely contains a problematic combination of profiles. """ results = {'individuals': [], 'ranges': []} if hi - lo <= 1: logging.info('Found %s as a problematic function profile', common_funcs[lo]) results['individuals'].append(common_funcs[lo]) return results mid = (lo + hi) // 2 lo_mid_prof = good.copy() # covers bad from lo:mid mid_hi_prof = good.copy() # covers bad from mid:hi for func in common_funcs[lo:mid]: lo_mid_prof[func] = bad[func] for func in common_funcs[mid:hi]: mid_hi_prof[func] = bad[func] lo_mid_verdict = decider.run(lo_mid_prof) mid_hi_verdict = decider.run(mid_hi_prof) if lo_mid_verdict == StatusEnum.BAD_STATUS: result = bisect_profiles(decider, good, bad, common_funcs, lo, mid) results['individuals'].extend(result['individuals']) results['ranges'].extend(result['ranges']) if mid_hi_verdict == StatusEnum.BAD_STATUS: result = bisect_profiles(decider, good, bad, common_funcs, mid, hi) results['individuals'].extend(result['individuals']) results['ranges'].extend(result['ranges']) # neither half is bad -> the issue is caused by several things occuring # in conjunction, and this combination crosses 'mid' if lo_mid_verdict == mid_hi_verdict == StatusEnum.GOOD_STATUS: problem_range = range_search(decider, good, bad, common_funcs, lo, hi) if problem_range: logging.info('Found %s as a problematic combination of profiles', str(problem_range)) results['ranges'].append(problem_range) return results def bisect_profiles_wrapper(decider, good, bad, perform_check=True): """Wrapper for recursive profile bisection.""" # Validate good and bad profiles are such, otherwise bisection reports noise # Note that while decider is a random mock, these assertions may fail. if perform_check: if decider.run(good, save_run=False) != StatusEnum.GOOD_STATUS: raise ValueError('Supplied good profile is not actually GOOD') if decider.run(bad, save_run=False) != StatusEnum.BAD_STATUS: raise ValueError('Supplied bad profile is not actually BAD') common_funcs = sorted(func for func in good if func in bad) if not common_funcs: return {'ranges': [], 'individuals': []} # shuffle because the results of our analysis can be quite order-dependent # but this list has no inherent ordering. By shuffling each time, the chances # of finding new, potentially interesting results are increased each time # the program is run random.shuffle(common_funcs) results = bisect_profiles(decider, good, bad, common_funcs, 0, len(common_funcs)) results['ranges'].sort() results['individuals'].sort() return results def range_search(decider, good, bad, common_funcs, lo, hi): """Searches for problematic range crossing mid border. The main inner algorithm is the following, which looks for the smallest possible ranges with problematic combinations. It starts the upper bound at the midpoint, and increments in halves until it gets a BAD profile. Then, it increments the lower bound (in halves) until the resultant profile is GOOD, and then we have a range that causes 'BAD'ness. It does this _NUM_RUNS_RANGE_SEARCH times, and shuffles the functions being looked at uniquely each time to try and get the smallest possible range of functions in a reasonable timeframe. """ average = lambda x, y: int(round((x + y) // 2.0)) def find_upper_border(good_copy, funcs, lo, hi, last_bad_val=None): """Finds the upper border of problematic range.""" mid = average(lo, hi) if mid == lo or mid == hi: return last_bad_val or hi for func in funcs[lo:mid]: good_copy[func] = bad[func] verdict = decider.run(good_copy) # reset for next iteration for func in funcs: good_copy[func] = good[func] if verdict == StatusEnum.BAD_STATUS: return find_upper_border(good_copy, funcs, lo, mid, mid) return find_upper_border(good_copy, funcs, mid, hi, last_bad_val) def find_lower_border(good_copy, funcs, lo, hi, last_bad_val=None): """Finds the lower border of problematic range.""" mid = average(lo, hi) if mid == lo or mid == hi: return last_bad_val or lo for func in funcs[lo:mid]: good_copy[func] = good[func] verdict = decider.run(good_copy) # reset for next iteration for func in funcs: good_copy[func] = bad[func] if verdict == StatusEnum.BAD_STATUS: return find_lower_border(good_copy, funcs, mid, hi, lo) return find_lower_border(good_copy, funcs, lo, mid, last_bad_val) lo_mid_funcs = [] mid_hi_funcs = [] min_range_funcs = [] for _ in range(_NUM_RUNS_RANGE_SEARCH): if min_range_funcs: # only examine range we've already narrowed to random.shuffle(lo_mid_funcs) random.shuffle(mid_hi_funcs) else: # consider lo-mid and mid-hi separately bc must cross border mid = (lo + hi) // 2 lo_mid_funcs = common_funcs[lo:mid] mid_hi_funcs = common_funcs[mid:hi] funcs = lo_mid_funcs + mid_hi_funcs hi = len(funcs) mid = len(lo_mid_funcs) lo = 0 # because we need the problematic pair to pop up before we can narrow it prof = good.copy() for func in lo_mid_funcs: prof[func] = bad[func] upper_border = find_upper_border(prof, funcs, mid, hi) for func in lo_mid_funcs + funcs[mid:upper_border]: prof[func] = bad[func] lower_border = find_lower_border(prof, funcs, lo, mid) curr_range_funcs = funcs[lower_border:upper_border] if not min_range_funcs or len(curr_range_funcs) < len(min_range_funcs): min_range_funcs = curr_range_funcs lo_mid_funcs = lo_mid_funcs[lo_mid_funcs.index(min_range_funcs[0]):] mid_hi_funcs = mid_hi_funcs[:mid_hi_funcs.index(min_range_funcs[-1]) + 1] if len(min_range_funcs) == 2: min_range_funcs.sort() return min_range_funcs # can't get any smaller min_range_funcs.sort() return min_range_funcs def check_good_not_bad(decider, good, bad): """Check if bad prof becomes GOOD by adding funcs it lacks from good prof""" bad_copy = bad.copy() for func in good: if func not in bad: bad_copy[func] = good[func] return decider.run(bad_copy) == StatusEnum.GOOD_STATUS def check_bad_not_good(decider, good, bad): """Check if good prof BAD after adding funcs bad prof has that good doesnt""" good_copy = good.copy() for func in bad: if func not in good: good_copy[func] = bad[func] return decider.run(good_copy) == StatusEnum.BAD_STATUS def parse_args(): parser = argparse.ArgumentParser( description=__doc__, formatter_class=argparse.RawDescriptionHelpFormatter) parser.add_argument( '--good_prof', required=True, help='Text-based "Good" profile for analysis') parser.add_argument( '--bad_prof', required=True, help='Text-based "Bad" profile for analysis') parser.add_argument( '--external_decider', required=True, help='External script that, given an AFDO profile, returns ' 'GOOD/BAD/SKIP') parser.add_argument( '--analysis_output_file', required=True, help='File to output JSON results to') parser.add_argument( '--state_file', default='%s/afdo_analysis_state.json' % os.getcwd(), help='File path containing state to load from initially, and will be ' 'overwritten with new state on each iteration') parser.add_argument( '--no_resume', action='store_true', help='If enabled, no initial state will be loaded and the program will ' 'run from the beginning') parser.add_argument( '--remove_state_on_completion', action='store_true', help='If enabled, state file will be removed once profile analysis is ' 'completed') parser.add_argument( '--seed', type=float, help='Float specifying seed for randomness') return parser.parse_args() def main(flags): logging.getLogger().setLevel(logging.INFO) if not flags.no_resume and flags.seed: # conflicting seeds raise RuntimeError('Ambiguous seed value; do not resume from existing ' 'state and also specify seed by command line flag') decider = DeciderState( flags.state_file, flags.external_decider, seed=flags.seed) if not flags.no_resume: decider.load_state() random.seed(decider.seed) with open(flags.good_prof) as good_f: good_items = text_to_json(good_f) with open(flags.bad_prof) as bad_f: bad_items = text_to_json(bad_f) bisect_results = bisect_profiles_wrapper(decider, good_items, bad_items) gnb_result = check_good_not_bad(decider, good_items, bad_items) bng_result = check_bad_not_good(decider, good_items, bad_items) results = { 'seed': decider.seed, 'bisect_results': bisect_results, 'good_only_functions': gnb_result, 'bad_only_functions': bng_result } with open(flags.analysis_output_file, 'wb') as f: json.dump(results, f, indent=2) if flags.remove_state_on_completion: os.remove(flags.state_file) logging.info('Removed state file %s following completion of script...', flags.state_file) else: completed_state_file = '%s.completed.%s' % (flags.state_file, str(date.today())) os.rename(flags.state_file, completed_state_file) logging.info('Stored completed state file as %s...', completed_state_file) return results if __name__ == '__main__': main(parse_args())