| #!/usr/bin/python |
| # Copyright 2013 The Chromium Authors. All rights reserved. |
| # Use of this source code is governed by a BSD-style license that can be |
| # found in the LICENSE file. |
| '''Generate stats of CQ usage.''' |
| |
| # sudo apt-get install pip; sudo pip install requests request_cache |
| import argparse |
| import collections |
| from datetime import timedelta, datetime |
| import itertools |
| import numpy |
| import operator |
| import re |
| import requests_cache |
| import time |
| import sys |
| |
| |
| class Unbuffered: |
| def __init__(self, stream): |
| self.stream = stream |
| def write(self, data): |
| self.stream.write(data) |
| self.stream.flush() |
| def __getattr__(self, attr): |
| return getattr(self.stream, attr) |
| sys.stdout = Unbuffered(sys.stdout) |
| |
| |
| CONFIG = { |
| 'chrome': { |
| 'target_base_url_regexps': [ |
| re.compile(r'^svn://svn\.chromium\.org/chrome/trunk/src'), |
| # pylint: disable=C0301 |
| re.compile(r'^https://chromium\.googlesource\.com/chromium/chromium/src(?:\.git)?(?:@[\w\-]+)?$'), |
| re.compile(r'^http://src\.chromium\.org/chrome/trunk/src'), |
| ], |
| }, |
| 'blink': { |
| 'target_base_url_regexps': [ |
| re.compile(r'^svn://svn\.chromium\.org/blink/(?:trunk/?)?$'), |
| # pylint: disable=C0301 |
| re.compile(r'^https://chromium\.googlesource\.com/chromium/blink(?:\.git)?(?:@[\w\-]+)?$'), |
| re.compile(r'^http://src\.chromium\.org/blink/(?:trunk/?)?$'), |
| ], |
| }, |
| 'skia': { |
| 'target_base_url_regexps': [ |
| re.compile(r'^http://skia.googlecode.com/svn/trunk'), |
| re.compile(r'^https://skia.googlecode.com/svn/trunk'), |
| ], |
| }, |
| } |
| config_name = None |
| |
| |
| def make_throttle_hook(timeout=1.0): |
| # pylint: disable=W0613 |
| def hook(response, *args, **kwargs): |
| print response.url |
| if not getattr(response, 'from_cache', False): |
| print 'sleeping' |
| time.sleep(timeout) |
| return response |
| return hook |
| |
| |
| # It seems reasonable to expect that rietveld can handle 20 query-per-second |
| # load from this script. Ask someone on the infra team before reducing this |
| # value. |
| seconds_between_requests = 0.05 |
| |
| requests_cache.install_cache('cq') |
| session = requests_cache.CachedSession() |
| # if args.clear: |
| # print 'Clearing cache...' |
| # session.cache.clear() |
| session.hooks = {'response': make_throttle_hook(seconds_between_requests)} |
| |
| |
| def fetch_recent_issues(limit, args, cursor=None): |
| search_url = ('https://codereview.chromium.org/search?format=json&' |
| 'limit=%d') % limit |
| if cursor: |
| search_url += '&cursor=%s' % cursor |
| if args.modified_after: |
| search_url += '&modified_after=%s' % args.modified_after |
| if args.modified_before: |
| search_url += '&modified_before=%s' % args.modified_before |
| response = session.get(search_url) |
| return response.json() |
| |
| |
| def get_target_base_url_regexps(): |
| return CONFIG[config_name]['target_base_url_regexps'] |
| |
| |
| def matches_target_base_url(url): |
| for regexp in get_target_base_url_regexps(): |
| match = regexp.match(url) |
| if match: |
| return True |
| return False |
| |
| |
| def issue_patch_string(issue_id, patch_id): |
| return '%s:%s' % (issue_id, patch_id) |
| |
| |
| def issue_display_url(issue_id): |
| return 'https://codereview.chromium.org/%s' % issue_id |
| |
| |
| def issue_url(issue_id): |
| return 'https://codereview.chromium.org/api/%s?messages=true' % issue_id |
| |
| |
| def date_from_iso_str(iso_str): |
| # Issues have one of two formats: |
| # 2013-10-17 16:43:04.391480 |
| # 2013-10-17 16:43:04 |
| try: |
| return datetime.strptime(iso_str, '%Y-%m-%d %H:%M:%S.%f') |
| except ValueError: |
| return datetime.strptime(iso_str, '%Y-%m-%d %H:%M:%S') |
| |
| |
| def round_timedelta(delta): |
| # We never care about the milliseconds when printing timedeltas: |
| return timedelta(seconds=round(delta.total_seconds())) |
| |
| |
| def fetch_issue(issue_id): |
| url = issue_url(issue_id) |
| this_json = session.get(url).json() |
| # pylint: disable=W0212 |
| cache_key = session.cache._url_to_key(url) |
| _, now = session.cache.get_response_and_time(cache_key) |
| return this_json, now |
| |
| |
| def format_line(values, aligns, widths): |
| values = map(str, values) |
| args = zip(values, aligns, widths) |
| return ' '.join([apply(align, (value, width)) |
| for value, align, width in args]) |
| |
| |
| class CQAttempt(object): |
| def __init__(self): |
| self.result = None |
| self.patch_id = None |
| self.issue_id = None |
| self.author = None |
| self.start_time = None |
| self.end_time = None |
| |
| @property |
| def issue_patch_string(self): |
| return issue_patch_string(self.issue_id, self.patch_id) |
| |
| @property |
| def duration(self): |
| return self.end_time - self.start_time |
| |
| |
| class CQAnalyzer(object): |
| def __init__(self): |
| self.state = None |
| self.issue = None |
| self.issue_id = None |
| self.author = None |
| self.patch_id = None |
| self.start_time = None |
| self.attempts = [] |
| self.manual_commits = set() |
| self.no_try_issues = set() |
| self.now = None |
| # issue_id -> time since CQ start |
| self.in_progress = {} |
| |
| # pylint: disable=C0301 |
| start_regexp = re.compile('''CQ is trying da patch. Follow status at |
| https://chromium-status.appspot.com/cq/(?P<author>.*)/(?P<issue_id>\d+)/(?P<patch_id>\d+)''') |
| committed_regexp = re.compile('Change committed as (?P<revision>\d+)') |
| # pylint: disable=C0301 |
| manual_commit_regexp = re.compile('Committed patchset #(?P<patch_id>\d+) manually as r(?P<revision>\d+)') |
| |
| def _reset(self): |
| self.state = None |
| self.author = None |
| self.patch_id = None |
| self.start_time = None |
| |
| def _start(self, patch_id, start_time, author=None): |
| if self.state == 'START' and self.patch_id == patch_id: |
| # print 'Restarted for patchset %s on %s' % ( |
| # patch_id, issue_display_url(self.issue_id)) |
| self._end('RESTART', start_time) |
| self.state = 'START' |
| self.patch_id = patch_id |
| self.author = author |
| assert start_time |
| self.start_time = start_time |
| |
| def _end(self, result, end_time): |
| if self.state != 'START': |
| print 'ERROR: %s for %s without start??' % ( |
| result, issue_display_url(self.issue_id)) |
| self._reset() |
| return |
| attempt = CQAttempt() |
| attempt.result = result |
| attempt.patch_id = self.patch_id |
| attempt.issue_id = self.issue_id |
| attempt.start_time = self.start_time |
| attempt.end_time = end_time |
| self.attempts.append(attempt) |
| self._reset() |
| |
| def _start_and_end(self, result, date): |
| self._start(result, date) |
| self._end(result, date) |
| |
| def _manual_commit(self, patch_id): |
| self.manual_commits.add(issue_patch_string(self.issue_id, patch_id)) |
| |
| def process_message(self, message): |
| text = message['text'] |
| date = date_from_iso_str(message['date']) |
| |
| match = self.manual_commit_regexp.match(text) |
| if match: |
| if self.start_time: |
| self._end('MANUAL_COMMIT', |
| date_from_iso_str(self.issue['modified'])) |
| patch_number = int(match.group('patch_id')) |
| # gcl dcommit talks in terms of patch numbers 1-5, we need to map |
| # those to patchset ids: |
| if len(self.issue['patchsets']) > (patch_number-1): |
| patch_id = self.issue['patchsets'][patch_number-1] |
| else: |
| print '%s missing patch number %d' % ( |
| self.issue_id, patch_number) |
| print self.issue['patchsets'] |
| print 'issue, now = fetch_issue(\'%s\')' % self.issue_id |
| patch_id = self.issue['patchsets'][-1] |
| self._manual_commit(patch_id) |
| return |
| |
| if message['sender'] != 'commit-bot@chromium.org': |
| return |
| |
| match = self.start_regexp.match(text) |
| if match: |
| self._start(match.group('patch_id'), date, match.group('author')) |
| return |
| match = self.committed_regexp.match(text) |
| if match: |
| self._end('SUCCESS', date) |
| return |
| |
| cq_end_messages = { |
| 'TRY': 'Retried try job', |
| 'APPLY': 'Failed to apply patch', |
| 'APPLY2': 'Failed to apply the patch', |
| 'COMPILE': 'Sorry for I got bad news for ya', |
| 'DESCRIPTION_CHANGED': ('Commit queue rejected this change because ' |
| 'the description'), |
| # This is too conservative. |
| 'REVIEWERS_CHANGED': 'List of reviewers changed.', |
| # User caused. |
| 'PATCH_CHANGED': 'Commit queue failed due to new patchset.', |
| # FAILED_TO_TRIGGER is a very serious failure, unclear why it |
| # happens! |
| 'FAILED_TO_TRIGGER': 'Failed to trigger a try job on', |
| # BINARY_FILE is just a bug in the CQ. |
| 'BINARY_FILE': 'Can\'t process patch for file', |
| 'BINARY_FILE2': 'Failed to request the patch to try', |
| # Unclear why UPDATE_STEP happens. Likely broken bots, shouldn't |
| # fail patches! |
| 'UPDATE_STEP': 'Step "update" is always a major failure.', |
| 'BERSERK': 'The commit queue went berserk', |
| 'INTERNAL_ERROR': 'Commit queue had an internal error.', |
| } |
| for result, message_text in cq_end_messages.items(): |
| if text.startswith(message_text): |
| self._end(result, date) |
| return |
| |
| cq_fail_to_start_messsages = { |
| 'FAILED_PATCHSET': 'Failed to get patchset properties', |
| 'NO_COMMENTS': 'No comments yet.', |
| 'NO_LGTM': 'No LGTM from a valid reviewer yet.', |
| } |
| for result, message_text in cq_fail_to_start_messsages.items(): |
| if text.startswith(message_text): |
| self._start_and_end(result, date) |
| return |
| |
| print 'Error %s has unknown message: %s' % ( |
| issue_display_url(self.issue_id), text) |
| self._end('UNKNOWN', date) |
| |
| def start_issue(self, issue, now): |
| # We may be dealing with cached data, so cache our concept of "now" |
| self.now = now |
| self.issue = issue |
| self.issue_id = issue['issue'] |
| |
| def end_issue(self, issue): |
| issue_id = issue['issue'] |
| assert issue_id == self.issue_id |
| if self.start_time: |
| if self.issue['commit']: |
| print '%s in progress? %s' % ( |
| round_timedelta(self.now - self.start_time), |
| issue_display_url(self.issue_id)) |
| self._end('IN_PROGRESS', self.now) |
| else: |
| # There are various reasons why the commit box may have |
| # been unchecked, including that the issue may be closed now. |
| # If those are not from a user, then that's a bug in rietveld |
| # and out of scope for this script. For now we're just ignoring |
| # cases where the box was unchecked. We could log an _end() |
| # event, but which time would we use? last_modified has at |
| # best a weak corrolation with the issue close or CQ checkbox. |
| self._reset() |
| # _reset() shouldn't be needed, but just in case. |
| self._reset() |
| self.issue_id = None |
| self.issue = None |
| |
| def process_issue(self, issue, now): |
| issue_id = issue['issue'] |
| |
| if re.search('^NOTRY=[tT][rR][uU][eE]$', issue['description'], re.M): |
| self.no_try_issues.add(issue_id) |
| |
| self.start_issue(issue, now) |
| for message in issue['messages']: |
| self.process_message(message) |
| # print '%(date)s: %(text)s' % message |
| self.end_issue(issue) |
| |
| def print_attempts_table(self): |
| result_getter = operator.attrgetter('result') |
| attempts = sorted(self.attempts, key=result_getter) |
| |
| col_aligns = (str.rjust, str.ljust, str.rjust, str.rjust) |
| col_widths = (5, 20, 16, 16) |
| col_headers = ('count', 'result', 'mean duration', 'median duration') |
| print |
| print ('CQ Attempts by result (there can be more than ' |
| 'one attempt on the same patch)') |
| print format_line(col_headers, col_aligns, col_widths) |
| print '-' * (sum(col_widths) + len(col_widths) - 1) |
| for result, group_itr in itertools.groupby(attempts, result_getter): |
| group = list(group_itr) |
| durations = map(operator.attrgetter('duration'), group) |
| mean = sum(durations, timedelta()) / len(group) |
| durations_seconds = map(timedelta.total_seconds, durations) |
| median_seconds = numpy.median(durations_seconds) |
| median = timedelta(seconds=round(median_seconds)) |
| values = (len(group), result, round_timedelta(mean), median) |
| print format_line(values, col_aligns, col_widths) |
| print |
| |
| |
| def main(): |
| parser = argparse.ArgumentParser() |
| parser.add_argument('--base-url-stats', action='store_true', |
| help='print base_url matching stats') |
| parser.add_argument('--chrome', action='store_true') |
| parser.add_argument('--clear', action='store_true', |
| help='clear the cache before starting') |
| parser.add_argument('--count', type=int, default=None, |
| help='number of issues to fetch') |
| parser.add_argument('--modified-after', default=None, |
| help=('search for issues modified after ' |
| 'this date YYYY-MM-DD')) |
| parser.add_argument('--modified-before', default=None, |
| help=('search for issues modified before ' |
| 'this date YYYY-MM-DD')) |
| parser.add_argument('--progress', help='Show progress', action='store_true') |
| parser.add_argument('--skia', action='store_true') |
| args = parser.parse_args() |
| |
| # Rietveld allows up to 1000 results per search query. I don't know if |
| # that's better for the server or not. We'll use 100 to be safe. |
| per_request_search_limit = 100 |
| if args.count: |
| per_request_search_limit = min(int(args.count/2), 100) |
| # Currently looking at the last 2000 entries. |
| target_count = args.count |
| if args.clear: |
| print 'Clearing cache...' |
| session.cache.clear() |
| global config_name |
| if args.chrome: |
| config_name = 'chrome' |
| elif args.skia: |
| config_name = 'skia' |
| else: |
| config_name = 'blink' |
| print 'Fetching and analyzing most recent issues...' |
| analyzer = CQAnalyzer() |
| |
| total_fetch_count = 0 |
| issue_count = 0 |
| cursor = None |
| url_counts = collections.Counter() |
| while True: |
| search_results = fetch_recent_issues(per_request_search_limit, args, |
| cursor) |
| if len(search_results['results']) == 0: |
| break |
| cursor = search_results['cursor'] |
| total_fetch_count += per_request_search_limit |
| |
| if args.base_url_stats: |
| url_counts.update([result['base_url'] |
| for result in search_results['results']]) |
| |
| for result in search_results['results']: |
| if not matches_target_base_url(result['base_url']): |
| continue |
| issue_count += 1 |
| if args.progress and (issue_count % 100 == 0): |
| print issue_count, |
| if target_count: |
| print target_count |
| issue, now = fetch_issue(result['issue']) |
| analyzer.process_issue(issue, now) |
| if target_count and issue_count >= target_count: |
| break |
| |
| if args.base_url_stats: |
| print |
| for url, count in url_counts.most_common(): |
| matches_target = matches_target_base_url(url) |
| print '%s %s %s' % (matches_target, count, url) |
| |
| print |
| print 'Found %s issues (in the %s most recent issues).' % ( |
| issue_count, total_fetch_count) |
| cq_issues = set([attempt.issue_id for attempt in analyzer.attempts]) |
| cq_issue_count = len(cq_issues) |
| cq_patches = set([attempt.issue_patch_string |
| for attempt in analyzer.attempts]) |
| cq_patch_count = len(cq_patches) |
| print ('%s issues (%d%%) (%d patches) tried the CQ, ' |
| 'resulting in %d CQ attempts.') % ( |
| cq_issue_count, 100 * cq_issue_count / issue_count, cq_patch_count, |
| len(analyzer.attempts)) |
| |
| no_try_issues = len(cq_issues & analyzer.no_try_issues) |
| gave_up_patches = len(cq_patches & analyzer.manual_commits) |
| print ('%s of those (%d%%) were committed manually (gave up). ' |
| '%s (%d%%) were marked NOTRY.') % ( |
| gave_up_patches, 100 * gave_up_patches / cq_issue_count, |
| no_try_issues, 100 * no_try_issues / cq_issue_count) |
| |
| analyzer.print_attempts_table() |
| |
| identifier_getter = operator.attrgetter('issue_patch_string') |
| attempts = sorted(analyzer.attempts, key=identifier_getter) |
| extra_user_clicks = 0 |
| eventually_success_durations = [] |
| eventually_success_attempts = [] |
| |
| # pylint: disable=W0612 |
| for identifier, group_itr in itertools.groupby(attempts, identifier_getter): |
| group = list(group_itr) |
| if group[0].issue_id in analyzer.no_try_issues: |
| continue |
| results = map(operator.attrgetter('result'), group) |
| # print '%s(%s): %s %s' % (identifier, len(group), total_time, results) |
| if 'SUCCESS' in results: |
| # 'RESTART' events may not require a user re-click? |
| user_initiated = filter(lambda result: result != 'RESTART', results) |
| extra_user_clicks += len(user_initiated) - 1 |
| durations = map(operator.attrgetter('duration'), group) |
| eventually_success_durations.append( |
| sum(durations, timedelta()).total_seconds()) |
| eventually_success_attempts.append(len(group)) |
| |
| print ('%s CQ starts (%d%%) were due a previous false-negative ' |
| '(CQ landed a patch it previously rejected)') % ( |
| extra_user_clicks, 100 * extra_user_clicks / len(analyzer.attempts)) |
| |
| print 'Patches which eventually land percentiles:' |
| for i in [10, 25, 50, 75, 90, 95, 99]: |
| eventually_success_durations_p = round(numpy.percentile( |
| eventually_success_durations, i)/(60*60), 3) |
| eventually_success_attempts_p = numpy.percentile( |
| eventually_success_attempts, i) |
| print '%d: %.3f hrs, %.3f attempts' % ( |
| i, eventually_success_durations_p, eventually_success_attempts_p) |
| |
| |
| if __name__ == '__main__': |
| sys.exit(main()) |
