poky/scripts/buildstats-diff

#!/usr/bin/python3

Script for comparing buildstats from two different builds

Copyright (c) 2016, Intel Corporation.

This program is free software; you can redistribute it and/or modify it

under the terms and conditions of the GNU General Public License,

version 2, as published by the Free Software Foundation.

This program is distributed in the hope it will be useful, but WITHOUT

ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or

FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for

more details.

import argparse import glob import json import logging import os import re import sys from collections import namedtuple from datetime import datetime, timedelta, tzinfo from operator import attrgetter

Setup logging

logging.basicConfig(level=logging.INFO) log = logging.getLogger()

class TimeZone(tzinfo): """Simple fixed-offset tzinfo""" def init(self, seconds, name): self._offset = timedelta(seconds=seconds) self._name = name

def utcoffset(self, dt):
    return self._offset

def tzname(self, dt):
    return self._name

def dst(self, dt):
    return None

TIMEZONES = {'UTC': TimeZone(0, 'UTC'), 'EET': TimeZone(7200, 'EET'), 'EEST': TimeZone(10800, 'EEST')}

taskdiff_fields = ('pkg', 'pkg_op', 'task', 'task_op', 'cputime1', 'cputime2', 'absdiff', 'reldiff') TaskDiff = namedtuple('TaskDiff', ' '.join(taskdiff_fields))

def to_datetime_obj(obj): """Helper for getting timestamps in datetime format""" if isinstance(obj, datetime): return obj else: return datetime.utcfromtimestamp(obj).replace(tzinfo=TIMEZONES['UTC'])

def read_buildstats_file(buildstat_file): """Convert buildstat text file into dict/json""" bs_json = {'iostat': {}, 'rusage': {}, 'child_rusage': {}} log.debug("Reading task buildstats from %s", buildstat_file) with open(buildstat_file) as fobj: for line in fobj.readlines(): key, val = line.split(':', 1) val = val.strip() if key == 'Started': start_time = to_datetime_obj(float(val)) bs_json['start_time'] = start_time elif key == 'Ended': end_time = to_datetime_obj(float(val)) elif key.startswith('IO '): split = key.split() bs_json['iostat'][split[1]] = int(val) elif key.find('rusage') >= 0: split = key.split() ru_key = split[-1] if ru_key in ('ru_stime', 'ru_utime'): val = float(val) else: val = int(val) ru_type = 'rusage' if split[0] == 'rusage' else
'child_rusage' bs_json[ru_type][ru_key] = val elif key == 'Status': bs_json['status'] = val bs_json['elapsed_time'] = end_time - start_time return bs_json

def read_buildstats_dir(bs_dir): """Read buildstats directory""" def split_nevr(nevr): """Split name and version information from recipe "nevr" string""" n_e_v, revision = nevr.rsplit('-', 1) match = re.match(r'^(?P\S+)-((?P[0-9]{1,5}))?(?P[0-9]\S*)$', n_e_v) if not match: # If we're not able to parse a version starting with a number, just # take the part after last dash match = re.match(r'^(?P\S+)-((?P[0-9]{1,5}))?(?P[^-]+)$', n_e_v) name = match.group('name') version = match.group('version') epoch = match.group('epoch') return name, epoch, version, revision

if os.path.isfile(os.path.join(bs_dir, 'build_stats')):
    top_dir = bs_dir
elif os.path.exists(bs_dir):
    subdirs = sorted(glob.glob(bs_dir + '/*'))
    if len(subdirs) > 1:
        log.warning("Multiple buildstats found, using the first one")
    top_dir = subdirs[0]
else:
    log.error("No such directory: %s", bs_dir)
    sys.exit(1)
log.debug("Reading buildstats directory %s", top_dir)
subdirs = os.listdir(top_dir)

# Handle "old" style directory structure
if len(subdirs) == 1 and re.match('^20[0-9]{12}$', subdirs[0]):
    top_dir = os.path.join(top_dir, subdirs[0])
    subdirs = os.listdir(top_dir)

buildstats = {}
for dirname in subdirs:
    recipe_dir = os.path.join(top_dir, dirname)
    if not os.path.isdir(recipe_dir):
        continue
    name, epoch, version, revision = split_nevr(dirname)
    recipe_bs = {'nevr': dirname,
                 'name': name,
                 'epoch': epoch,
                 'version': version,
                 'revision': revision,
                 'tasks': {}}
    for task in os.listdir(recipe_dir):
        recipe_bs['tasks'][task] = read_buildstats_file(
                os.path.join(recipe_dir, task))
    if name in buildstats:
        log.error("Cannot handle multiple versions of the same package (%s)",
                  name)
        sys.exit(1)
    buildstats[name] = recipe_bs

return buildstats

def read_buildstats_json(path): """Read buildstats from JSON file""" buildstats = {} with open(path) as fobj: bs_json = json.load(fobj) for recipe_bs in bs_json: if recipe_bs['name'] in buildstats: log.error("Cannot handle multiple versions of the same package (%s)", recipe_bs['name']) sys.exit(1)

    if recipe_bs['epoch'] is None:
        recipe_bs['nevr'] = "{}-{}-{}".format(recipe_bs['name'], recipe_bs['version'], recipe_bs['revision'])
    else:
        recipe_bs['nevr'] = "{}-{}_{}-{}".format(recipe_bs['name'], recipe_bs['epoch'], recipe_bs['version'], recipe_bs['revision'])
    buildstats[recipe_bs['name']] = recipe_bs

return buildstats

def read_buildstats(path): """Read buildstats""" if os.path.isfile(path): return read_buildstats_json(path) else: return read_buildstats_dir(path)

def print_ver_diff(bs1, bs2): """Print package version differences""" pkgs1 = set(bs1.keys()) pkgs2 = set(bs2.keys()) new_pkgs = pkgs2 - pkgs1 deleted_pkgs = pkgs1 - pkgs2

echanged = []
vchanged = []
rchanged = []
unchanged = []
common_pkgs = pkgs2.intersection(pkgs1)
if common_pkgs:
    for pkg in common_pkgs:
        if bs1[pkg]['epoch'] != bs2[pkg]['epoch']:
            echanged.append(pkg)
        elif bs1[pkg]['version'] != bs2[pkg]['version']:
            vchanged.append(pkg)
        elif bs1[pkg]['revision'] != bs2[pkg]['revision']:
            rchanged.append(pkg)
        else:
            unchanged.append(pkg)

maxlen = max([len(pkg) for pkg in pkgs1.union(pkgs2)])
fmt_str = "  {:{maxlen}} ({})"

if unchanged:

print("\nUNCHANGED PACKAGES:")

print("-------------------")

maxlen = max([len(pkg) for pkg in unchanged])

for pkg in sorted(unchanged):

print(fmt_str.format(pkg, bs2[pkg]['nevr'], maxlen=maxlen))

if new_pkgs:
    print("\nNEW PACKAGES:")
    print("-------------")
    for pkg in sorted(new_pkgs):
        print(fmt_str.format(pkg, bs2[pkg]['nevr'], maxlen=maxlen))

if deleted_pkgs:
    print("\nDELETED PACKAGES:")
    print("-----------------")
    for pkg in sorted(deleted_pkgs):
        print(fmt_str.format(pkg, bs1[pkg]['nevr'], maxlen=maxlen))

fmt_str = "  {0:{maxlen}} {1:<20}    ({2})"
if rchanged:
    print("\nREVISION CHANGED:")
    print("-----------------")
    for pkg in sorted(rchanged):
        field1 = "{} -> {}".format(pkg, bs1[pkg]['revision'], bs2[pkg]['revision'])
        field2 = "{} -> {}".format(bs1[pkg]['nevr'], bs2[pkg]['nevr'])
        print(fmt_str.format(pkg, field1, field2, maxlen=maxlen))

if vchanged:
    print("\nVERSION CHANGED:")
    print("----------------")
    for pkg in sorted(vchanged):
        field1 = "{} -> {}".format(bs1[pkg]['version'], bs2[pkg]['version'])
        field2 = "{} -> {}".format(bs1[pkg]['nevr'], bs2[pkg]['nevr'])
        print(fmt_str.format(pkg, field1, field2, maxlen=maxlen))

if echanged:
    print("\nEPOCH CHANGED:")
    print("--------------")
    for pkg in sorted(echanged):
        field1 = "{} -> {}".format(pkg, bs1[pkg]['epoch'], bs2[pkg]['epoch'])
        field2 = "{} -> {}".format(bs1[pkg]['nevr'], bs2[pkg]['nevr'])
        print(fmt_str.format(pkg, field1, field2, maxlen=maxlen))

def task_time(task): """Calculate sum of user and system time taken by a task""" cputime = task['rusage']['ru_stime'] + task['rusage']['ru_utime'] +
task['child_rusage']['ru_stime'] + task['child_rusage']['ru_utime'] return cputime

def print_task_diff(bs1, bs2, min_cputime=0, min_timediff=0, sort_by=('absdiff',)): """Diff task execution times""" tasks_diff = [] pkg_maxlen = 0 task_maxlen = 0

pkgs = set(bs1.keys()).union(set(bs2.keys()))
for pkg in pkgs:
    if len(pkg) > pkg_maxlen:
        pkg_maxlen = len(pkg)
    tasks1 = bs1[pkg]['tasks'] if pkg in bs1 else {}
    tasks2 = bs2[pkg]['tasks'] if pkg in bs2 else {}
    if not tasks1:
        pkg_op = '+ '
    elif not tasks2:
        pkg_op = '- '
    else:
        pkg_op = '  '

    for task in set(tasks1.keys()).union(set(tasks2.keys())):
        if len(task) > task_maxlen:
            task_maxlen = len(task)

        t1 = task_time(bs1[pkg]['tasks'][task]) if task in tasks1 else 0
        t2 = task_time(bs2[pkg]['tasks'][task]) if task in tasks2 else 0
        task_op = '  '
        if t1 == 0:
            reldiff = float('inf')
            task_op = '+ '
        else:
            reldiff = 100 * (t2 - t1) / t1
            if t2 == 0:
                task_op = '- '

        tasks_diff.append(TaskDiff(pkg, pkg_op, task, task_op, t1, t2, t2-t1, reldiff))

if min_cputime:
    print("Ignoring tasks shorter than {}s".format(min_cputime))
if min_timediff:
    print("Ignoring time differences shorter than {}s".format(min_timediff))

print()
print("  {:{pkg_maxlen}}   {:{task_maxlen}} {:>8} {:>10} {:>10}    {}".format(
        'PKG', 'TASK', 'ABSDIFF', 'RELDIFF', 'CPUTIME1', 'CPUTIME2',
        pkg_maxlen=pkg_maxlen, task_maxlen=task_maxlen))

# Sort our list
for field in reversed(sort_by):
    if field.startswith('-'):
        field = field[1:]
        reverse = True
    else:
        reverse = False
    tasks_diff = sorted(tasks_diff, key=attrgetter(field), reverse=reverse)

for diff in tasks_diff:
    cputime = max(diff.cputime1, diff.cputime2)
    if cputime > min_cputime:
        if abs(diff.absdiff) > min_timediff:
            task_prefix = diff.task_op if diff.pkg_op == '  ' else '  '
            print("{}{:{pkg_maxlen}} {}{:{task_maxlen}} {:+7.1f}s {:+9.1f}% {:9.1f}s -> {:.1f}s".format(
                    diff.pkg_op, diff.pkg, task_prefix, diff.task, diff.absdiff, diff.reldiff, diff.cputime1, diff.cputime2,
                    pkg_maxlen=pkg_maxlen, task_maxlen=task_maxlen))
        else:
            log.debug("Filtering out %s (difference of %0.1fs)", task, diff.absdiff)
    else:
        log.debug("Filtering out %s (%0.1fs)", task, cputime)

def print_timediff_summary(bs1, bs2): """Print summary of the timediffs""" def total_cputime(buildstats): sum = 0.0 for recipe_data in buildstats.values(): for task_data in recipe_data['tasks'].values(): sum += task_time(task_data) return sum

def hms_time(secs):
    """Get time in human-readable HH:MM:SS format"""
    h = int(secs / 3600)
    m = int((secs % 3600) / 60)
    s = secs % 60
    if h == 0:
        return "{:02d}:{:04.1f}".format(m, s)
    else:
        return "{:d}:{:02d}:{:04.1f}".format(h, m, s)

total1 = total_cputime(bs1)
total2 = total_cputime(bs2)
print("\nCumulative CPU Time:")
print ("  {:+.1f}s    {:+.1f}%    {} ({:.1f}s) -> {} ({:.1f}s)".format(
            total2 - total1, 100 * (total2-total1) / total1,
            hms_time(total1), total1, hms_time(total2), total2))

def parse_args(argv): """Parse cmdline arguments""" description=""" Script for comparing buildstats of two separate builds.""" parser = argparse.ArgumentParser( formatter_class=argparse.ArgumentDefaultsHelpFormatter, description=description)

parser.add_argument('--debug', '-d', action='store_true',
                    help="Verbose logging")
parser.add_argument('--ver-diff', action='store_true',
                    help="Show package version differences and exit")
parser.add_argument('--min-time', default=3.0, type=float,
                    help="Filter out tasks shorter than MIN_TIME seconds")
parser.add_argument('--min-timediff', default=1.0, type=float,
                    help="Filter out tasks whose difference in cputime is "
                         "less that  MIN_TIMEDIFF seconds")
parser.add_argument('--sort-by', default='absdiff',
                    help="Comma-separated list of field sort order. "
                         "Prepend the field name with '-' for reversed sort. "
                         "Available fields are: {}".format(', '.join(taskdiff_fields)))
parser.add_argument('buildstats1', metavar='BUILDSTATS1', help="'Left' buildstat")
parser.add_argument('buildstats2', metavar='BUILDSTATS2', help="'Right' buildstat")

return parser.parse_args(argv)

def main(argv=None): """Script entry point""" args = parse_args(argv) if args.debug: log.setLevel(logging.DEBUG)

# Validate sort fields
sort_by = []
for field in args.sort_by.split(','):
    if field.lstrip('-') not in taskdiff_fields:
        log.error("Invalid sort field '%s' (must be one of: %s)" %
                  (field, ', '.join(taskdiff_fields)))
        sys.exit(1)
    sort_by.append(field)


bs1 = read_buildstats(args.buildstats1)
bs2 = read_buildstats(args.buildstats2)

if args.ver_diff:
    print_ver_diff(bs1, bs2)
else:
    print_task_diff(bs1, bs2, args.min_time, args.min_timediff, sort_by)
    print_timediff_summary(bs1, bs2)

return 0

if name == "main": sys.exit(main())