| # -*- coding: utf-8 -*- |
| # Copyright 2017 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. |
| |
| """Invokes git bisect to find culprit commit.""" |
| |
| from __future__ import print_function |
| |
| import datetime |
| |
| from chromite.cros_bisect import common |
| from chromite.lib import cros_build_lib |
| from chromite.lib import cros_logging as logging |
| from chromite.lib import git |
| |
| |
| class GitBisectorException(Exception): |
| """Exception raised for GitBisector error.""" |
| pass |
| |
| |
| class GitBisector(common.OptionsChecker): |
| """Bisects suspicious commits in a git repository. |
| |
| Before bisect, it does sanity check for the given good and bad commit. Then |
| it extracts metric scores for both commits as baseline to determine the |
| upcoming bisect candidate's status. |
| |
| It finds first bad commit within given good and bad commit using "git bisect" |
| command. For each commit, it uses builder to build package to verify and |
| deploy it to DUT (device under test). And asks evaluator to extract score |
| of the commit. It is treated as good commit i the score is closer to user |
| specified good commit. |
| |
| Finally, it outputs git bisect result. |
| """ |
| |
| REQUIRED_ARGS = ('good', 'bad', 'remote', 'eval_repeat', 'auto_threshold', |
| 'board', 'eval_raise_on_error') |
| |
| def __init__(self, options, builder, evaluator): |
| """Constructor. |
| |
| Args: |
| options: An argparse.Namespace to hold command line arguments. Should |
| contain: |
| * good: Last known good commit. |
| * bad: Last known bad commit. |
| * remote: DUT (refer lib.commandline.Device). |
| * eval_repeat: Run test for N times. None means 1. |
| * auto_threshold: True to set threshold automatically without prompt. |
| * board: board name of the DUT. |
| * eval_raise_on_error: If set, raises if evaluation failed. |
| builder: Builder to build/deploy image. Should contain repo_dir. |
| evaluator: Evaluator to get score |
| """ |
| super(GitBisector, self).__init__(options) |
| self.good_commit = options.good |
| self.bad_commit = options.bad |
| self.remote = options.remote |
| self.eval_repeat = options.eval_repeat |
| self.builder = builder |
| self.evaluator = evaluator |
| self.repo_dir = self.builder.repo_dir |
| self.auto_threshold = options.auto_threshold |
| self.board = options.board |
| self.eval_raise_on_error = options.eval_raise_on_error |
| |
| # Initialized in ObtainBisectBoundaryScore(). |
| self.good_commit_info = None |
| self.bad_commit_info = None |
| |
| # Record bisect log (list of CommitInfo). |
| self.bisect_log = [] |
| |
| # If the distance between current commit's score and given good commit is |
| # shorter than threshold, treat the commit as good one. Its default value |
| # comes from evaluator's THRESHOLD constant. If it is None (undefined), |
| # the bisector will prompt user to input threshold after obtaining both |
| # sides' score. |
| self.threshold = evaluator.THRESHOLD |
| |
| # Set auto_threshold to True if the threshold is preset. |
| if self.threshold is not None: |
| self.auto_threshold = True |
| |
| # Init with empty CommitInfo. Will update in UpdateCurrentCommit(). |
| self.current_commit = common.CommitInfo() |
| |
| def SetUp(self): |
| """Sets up environment to bisect.""" |
| logging.info('Set up builder environment.') |
| self.builder.SetUp() |
| |
| @staticmethod |
| def CheckCommitFormat(commit): |
| """Checks if commit is the acceptable format. |
| |
| For git_bisector, commit should be SHA1. Child class may override it. |
| |
| Args: |
| commit: commit string. |
| |
| Returns: |
| Normalized commit. None if the format is unacceptable. |
| """ |
| if git.IsSHA1(commit, full=False): |
| return commit |
| return None |
| |
| def Git(self, command): |
| """Wrapper of git.RunGit. |
| |
| It passes self.repo_dir as git_repo to git.RunGit. |
| |
| Args: |
| command: git command. |
| |
| Returns: |
| A CommandResult object. |
| """ |
| return git.RunGit(self.repo_dir, command) |
| |
| def UpdateCurrentCommit(self): |
| """Updates self.current_commit.""" |
| result = self.Git(['show', '--no-patch', '--format=%h %ct %s']) |
| if result.returncode != 0: |
| logging.error('Failed to update current commit info.') |
| return |
| |
| fields = result.output.strip().split() |
| if len(fields) < 3: |
| logging.error('Failed to update current commit info.') |
| return |
| sha1 = fields[0] |
| timestamp = int(fields[1]) |
| title = ' '.join(fields[2:]) |
| self.current_commit = common.CommitInfo(sha1=sha1, title=title, |
| timestamp=timestamp) |
| |
| def GetCommitTimestamp(self, sha1): |
| """Obtains given commit's timestamp. |
| |
| Args: |
| sha1: Commit's SHA1 to look up. |
| |
| Returns: |
| timestamp in integer. None if the commit does not exist. |
| """ |
| result = self.Git(['show', '--no-patch', '--format=%ct', sha1]) |
| if result.returncode == 0: |
| try: |
| return int(result.output.strip()) |
| except ValueError: |
| pass |
| return None |
| |
| def SanityCheck(self): |
| """Checks if both last-known-good and bad commits exists. |
| |
| Also, last-known-good commit should be earlier than bad one. |
| |
| Returns: |
| True if both last-known-good and bad commits exist. |
| """ |
| logging.info('Perform sanity check on good commit %s and bad commit %s', |
| self.good_commit, self.bad_commit) |
| # Builder is lazy syncing to HEAD. Sync to HEAD if good_commit or bad_commit |
| # does not exist in repo. |
| if (not git.DoesCommitExistInRepo(self.repo_dir, self.good_commit) or |
| not git.DoesCommitExistInRepo(self.repo_dir, self.bad_commit)): |
| logging.info( |
| 'Either good commit (%s) or bad commit (%s) not found in repo. ' |
| 'Try syncing to HEAD first.', self.good_commit, self.bad_commit) |
| self.builder.SyncToHead() |
| else: |
| logging.info( |
| 'Both good commit (%s) and bad commit (%s) are found in repo. ' |
| 'No need to update repo.', self.good_commit, self.bad_commit) |
| |
| good_commit_timestamp = self.GetCommitTimestamp(self.good_commit) |
| if not good_commit_timestamp: |
| logging.error('Sanity check failed: good commit %s does not exist.', |
| self.good_commit) |
| return False |
| bad_commit_timestamp = self.GetCommitTimestamp(self.bad_commit) |
| if not bad_commit_timestamp: |
| logging.error('Sanity check failed: bad commit %s does not exist.', |
| self.bad_commit) |
| return False |
| |
| # TODO(deanliao): Consider the case that we want to find a commit that |
| # fixed a problem. |
| if bad_commit_timestamp < good_commit_timestamp: |
| logging.error( |
| 'Sanity check failed: good commit (%s) timestamp: %s should be ' |
| 'earlier than bad commit (%s): %s', |
| self.good_commit, good_commit_timestamp, |
| self.bad_commit, bad_commit_timestamp) |
| return False |
| return True |
| |
| def ObtainBisectBoundaryScoreImpl(self, good_side): |
| """The worker of obtaining score of either last-known-good or bad commit. |
| |
| It is used to be overridden by derived class without re-implement |
| ObtainBisectBoundaryScore(). |
| |
| Args: |
| good_side: True if it evaluates score for last-known-good. False for |
| last-known-bad commit. |
| |
| Returns: |
| Evaluated score. |
| """ |
| commit = self.good_commit if good_side else self.bad_commit |
| commit_label = 'good' if good_side else 'bad' |
| logging.notice('Obtaining score of %s commit: %s', commit_label, commit) |
| self.Git(['checkout', commit]) |
| return self.BuildDeployEval() |
| |
| def ObtainBisectBoundaryScore(self): |
| """Evaluates last known good and bad commit. |
| |
| In order to give user a reference when setting threshold, evaluates |
| designated benchmark on both last-known-good and last-known-bad commits. |
| It builds, deploys and evaluates both good and bad images on the DUT. |
| """ |
| good_score = self.ObtainBisectBoundaryScoreImpl(True) |
| self.good_commit_info = self.current_commit |
| self.good_commit_info.label = 'last-known-good ' |
| if good_score is None: |
| logging.error('Unable to obtain last-known-good score.') |
| return False |
| |
| bad_score = self.ObtainBisectBoundaryScoreImpl(False) |
| self.bad_commit_info = self.current_commit |
| self.bad_commit_info.label = 'last-known-bad ' |
| if bad_score is None: |
| logging.error('Unable to obtain last-known-bad score.') |
| return False |
| |
| if good_score == bad_score: |
| logging.error( |
| 'Last-known-good %s should be different from last-known-bad %s', |
| good_score, bad_score) |
| return False |
| |
| return True |
| |
| def GetThresholdFromUser(self): |
| """Gets threshold that decides good/bad commit. |
| |
| It gives user the measured last known good and bad score's statistics to |
| help user determine a reasonable threshold. |
| |
| If self.auto_threshold is set, instead of prompting user to pick threshold, |
| it uses half of distance between good and bad commit score as threshold. |
| """ |
| # If threshold is assigned, skip it. |
| if self.threshold is not None: |
| return True |
| |
| good_score = self.good_commit_info.score |
| bad_score = self.bad_commit_info.score |
| logging.notice('Good commit score mean: %.3f STD: %.3f\n' |
| 'Bad commit score mean: %.3f STD: %.3f', |
| good_score.mean, good_score.std, |
| bad_score.mean, bad_score.std) |
| if self.auto_threshold: |
| splitter = (good_score.mean + bad_score.mean) / 2.0 |
| self.threshold = abs(good_score.mean - splitter) |
| logging.notice('Automatically pick threshold: %.3f', self.threshold) |
| return True |
| |
| ref_score_min = min(good_score.mean, bad_score.mean) |
| ref_score_max = max(good_score.mean, bad_score.mean) |
| success = False |
| retry = 3 |
| for _ in range(retry): |
| try: |
| splitter = float(cros_build_lib.GetInput( |
| 'Please give a threshold that tell apart good and bad commit ' |
| '(within range [%.3f, %.3f]: ' % (ref_score_min, ref_score_max))) |
| except ValueError: |
| logging.error('Threshold should be a floating number.') |
| continue |
| |
| if ref_score_min <= splitter <= ref_score_max: |
| self.threshold = abs(good_score.mean - splitter) |
| success = True |
| break |
| else: |
| logging.error('Threshold should be within range [%.3f, %.3f]', |
| ref_score_min, ref_score_max) |
| else: |
| logging.error('Wrong threshold input for %d times. Terminate.', retry) |
| |
| return success |
| |
| def BuildDeploy(self): |
| """Builds with current commit and deploys to DUT. |
| |
| It is the default behavior of BuildDeployEval(). |
| """ |
| # TODO(deanliao): Handle build/deploy fail case. |
| build_label = self.current_commit.sha1 |
| build_to_deploy = self.builder.Build(build_label) |
| self.builder.Deploy(self.remote, build_to_deploy, build_label) |
| |
| def BuildDeployEval(self, eval_label=None, customize_build_deploy=None): |
| """Builds the image, deploys to DUT and evaluates performance. |
| |
| Args: |
| build_deploy: If set, builds current commit and deploys it to DUT. |
| eval_label: Label for the evaluation. Default: current commit SHA1. |
| customize_build_deploy: Method object if specified, call it instead of |
| default self.BuildDeploy(). |
| |
| Returns: |
| Evaluation result. |
| |
| Raises: |
| GitBisectorException if self.eval_raise_on_error and score is empty. |
| """ |
| self.UpdateCurrentCommit() |
| if not eval_label: |
| eval_label = self.current_commit.sha1 |
| |
| score = self.evaluator.CheckLastEvaluate(eval_label, self.eval_repeat) |
| if len(score) > 0: |
| logging.info('Found last evaluated result for %s: %s', eval_label, |
| score) |
| self.current_commit.score = score |
| else: |
| if customize_build_deploy: |
| customize_build_deploy() |
| else: |
| self.BuildDeploy() |
| self.current_commit.score = self.evaluator.Evaluate( |
| self.remote, eval_label, self.eval_repeat) |
| |
| self.bisect_log.append(self.current_commit) |
| if not self.current_commit.score and self.eval_raise_on_error: |
| raise GitBisectorException('Unable to obtain evaluation score') |
| return self.current_commit.score |
| |
| def LabelBuild(self, score): |
| """Determines if a build is good. |
| |
| Args: |
| score: evaluation score of the build. |
| |
| Returns: |
| 'good' if the score is closer to given good one; otherwise (including |
| score is None), 'bad'. |
| """ |
| label = 'bad' |
| if not score: |
| logging.error('No score. Marked as bad.') |
| return label |
| |
| good_score = self.good_commit_info.score |
| bad_score = self.bad_commit_info.score |
| ref_score_min = min(good_score.mean, bad_score.mean) |
| ref_score_max = max(good_score.mean, bad_score.mean) |
| if ref_score_min < score.mean < ref_score_max: |
| # Within (good_score, bad_score) |
| if abs(good_score.mean - score.mean) <= self.threshold: |
| label = 'good' |
| else: |
| dist_good = abs(good_score.mean - score.mean) |
| dist_bad = abs(bad_score.mean - score.mean) |
| if dist_good < dist_bad: |
| label = 'good' |
| logging.info('Score %.3f marked as %s', score.mean, label) |
| return label |
| |
| def GitBisect(self, bisect_op): |
| """Calls git bisect and logs result. |
| |
| Args: |
| bisect_op: git bisect subcommand list. |
| |
| Returns: |
| A CommandResult object. |
| done: True if bisect ends. |
| """ |
| command = ['bisect'] + bisect_op |
| command_str = cros_build_lib.CmdToStr(['git'] + command) |
| result = self.Git(command) |
| done = False |
| log_msg = [command_str] |
| if result.output: |
| log_msg.append('(output): %s' % result.output.strip()) |
| if result.error: |
| log_msg.append('(error): %s' % result.error.strip()) |
| if result.returncode != 0: |
| log_msg.append('(returncode): %d' % result.returncode) |
| |
| log_msg = '\n'.join(log_msg) |
| if result.error or result.returncode != 0: |
| logging.error(log_msg) |
| else: |
| logging.info(log_msg) |
| |
| if result.output: |
| if 'is the first bad commit' in result.output.splitlines()[0]: |
| done = True |
| return result, done |
| |
| @staticmethod |
| def CommitInfoToStr(info): |
| """Converts CommitInfo to string. |
| |
| Args: |
| info: A CommitInfo object. |
| |
| Returns: |
| Stringfied CommitInfo. |
| """ |
| timestamp = datetime.datetime.fromtimestamp(info.timestamp).isoformat(' ') |
| score = 'Score(mean: %.3f std: %.3f)' % (info.score.mean, info.score.std) |
| return ' '.join([info.label, timestamp, score, info.sha1, info.title]) |
| |
| def PrepareBisect(self): |
| """Performs sanity checks and obtains bisect boundary score before bisect. |
| |
| Returns: |
| False if there's something wrong. |
| """ |
| return (self.SanityCheck() and |
| self.ObtainBisectBoundaryScore() and |
| self.GetThresholdFromUser()) |
| |
| def Run(self): |
| """Bisects culprit commit. |
| |
| Returns: |
| Culprit commit's SHA1. None if culprit not found. |
| """ |
| if not self.PrepareBisect(): |
| return None |
| |
| self.GitBisect(['reset']) |
| bisect_done = False |
| culprit_commit = None |
| nth_bisect = 0 |
| try: |
| with cros_build_lib.TimedSection() as timer: |
| self.GitBisect(['start']) |
| self.GitBisect(['bad', self.bad_commit]) |
| self.GitBisect(['good', self.good_commit]) |
| while not bisect_done: |
| metric_score = self.BuildDeployEval() |
| bisect_op = self.LabelBuild(metric_score) |
| nth_bisect += 1 |
| self.current_commit.label = '%2d-th-bisect-%-4s' % (nth_bisect, |
| bisect_op) |
| logging.notice('Mark %s as %s. Score: %s', self.current_commit.sha1, |
| bisect_op, metric_score) |
| bisect_result, bisect_done = self.GitBisect([bisect_op]) |
| if bisect_done: |
| culprit_commit = bisect_result.output.splitlines()[1:] |
| if bisect_done: |
| logging.info('git bisect done. Elapsed time: %s', timer.delta) |
| finally: |
| self.GitBisect(['log']) |
| self.GitBisect(['reset']) |
| |
| # Emit bisect report. |
| self.bisect_log.sort(key=lambda x: x.timestamp) |
| logging.notice( |
| 'Bisect log (sort by time):\n' + |
| '\n'.join(map(self.CommitInfoToStr, self.bisect_log))) |
| |
| if culprit_commit: |
| logging.notice('\n'.join(['Culprit commit:'] + culprit_commit)) |
| # First line: commit <SHA> |
| return culprit_commit[0].split()[1] |
| else: |
| logging.notice('Culprit not found.') |
| return None |