path: root/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 math
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', 'value1', 'value2',
                   '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'])


class BSTask(dict):
    def __init__(self, *args, **kwargs):
        self['start_time'] = None
        self['elapsed_time'] = None
        self['status'] = None
        self['iostat'] = {}
        self['rusage'] = {}
        self['child_rusage'] = {}
        super(BSTask, self).__init__(*args, **kwargs)

    @property
    def cputime(self):
        """Sum of user and system time taken by the task"""
        return self['rusage']['ru_stime'] + self['rusage']['ru_utime'] + \
               self['child_rusage']['ru_stime'] + self['child_rusage']['ru_utime']

    @property
    def read_bytes(self):
        """Bytes read from the block layer"""
        return self['iostat']['read_bytes']

    @property
    def write_bytes(self):
        """Bytes written to the block layer"""
        return self['iostat']['write_bytes']

def read_buildstats_file(buildstat_file):
    """Convert buildstat text file into dict/json"""
    bs_task = BSTask()
    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_task['start_time'] = start_time
            elif key == 'Ended':
                end_time = to_datetime_obj(float(val))
            elif key.startswith('IO '):
                split = key.split()
                bs_task['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_task[ru_type][ru_key] = val
            elif key == 'Status':
                bs_task['status'] = val
    bs_task['elapsed_time'] = end_time - start_time
    return bs_task


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<name>\S+)-((?P<epoch>[0-9]{1,5})_)?(?P<version>[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<name>\S+)-((?P<epoch>[0-9]{1,5})_)?(?P<version>[^-]+)$',
                             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'])

        for task, data in recipe_bs['tasks'].copy().items():
            recipe_bs['tasks'][task] = BSTask(data)

        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 print_task_diff(bs1, bs2, val_type, min_val=0, min_absdiff=0, sort_by=('absdiff',)):
    """Diff task execution times"""
    def val_to_str(val, human_readable=False):
        """Convert raw value to printable string"""
        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)

        if val_type == 'cputime':
            if human_readable:
                return hms_time(val)
            else:
                return "{:.1f}s".format(val)
        elif 'bytes' in val_type and human_readable:
                prefix = ['', 'Ki', 'Mi', 'Gi', 'Ti', 'Pi']
                dec = int(math.log(val, 2) / 10)
                prec = 1 if dec > 0 else 0
                return "{:.{prec}f}{}B".format(val / (2 ** (10 * dec)),
                                               prefix[dec], prec=prec)
        return str(int(val))

    def sum_vals(buildstats):
        """Get cumulative sum of all tasks"""
        total = 0.0
        for recipe_data in buildstats.values():
            for bs_task in recipe_data['tasks'].values():
                total += getattr(bs_task, val_type)
        return total

    tasks_diff = []

    if min_val:
        print("Ignoring tasks less than {} ({})".format(
                val_to_str(min_val, True), val_to_str(min_val)))
    if min_absdiff:
        print("Ignoring differences less than {} ({})".format(
                val_to_str(min_absdiff, True), val_to_str(min_absdiff)))

    # Prepare the data
    pkgs = set(bs1.keys()).union(set(bs2.keys()))
    for pkg in pkgs:
        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())):
            task_op = '  '
            if task in tasks1:
                val1 = getattr(bs1[pkg]['tasks'][task], val_type)
            else:
                task_op = '+ '
                val1 = 0
            if task in tasks2:
                val2 = getattr(bs2[pkg]['tasks'][task], val_type)
            else:
                val2 = 0
                task_op = '- '

            if val1 == 0:
                reldiff = float('inf')
            else:
                reldiff = 100 * (val2 - val1) / val1

            if max(val1, val2) < min_val:
                log.debug("Filtering out %s:%s (%s)", pkg, task,
                          val_to_str(max(val1, val2)))
                continue
            if abs(val2 - val1) < min_absdiff:
                log.debug("Filtering out %s:%s (difference of %s)", pkg, task,
                          val_to_str(val2-val1))
                continue
            tasks_diff.append(TaskDiff(pkg, pkg_op, task, task_op, val1, val2,
                                       val2-val1, reldiff))

    # 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)

    linedata = [('  ', 'PKG', '  ', 'TASK', 'ABSDIFF', 'RELDIFF',
                val_type.upper() + '1', val_type.upper() + '2')]
    field_lens = dict([('len_{}'.format(i), len(f)) for i, f in enumerate(linedata[0])])

    # Prepare fields in string format and measure field lengths
    for diff in tasks_diff:
        task_prefix = diff.task_op if diff.pkg_op == '  ' else '  '
        linedata.append((diff.pkg_op, diff.pkg, task_prefix, diff.task,
                         val_to_str(diff.absdiff),
                         '{:+.1f}%'.format(diff.reldiff),
                         val_to_str(diff.value1),
                         val_to_str(diff.value2)))
        for i, field in enumerate(linedata[-1]):
            key = 'len_{}'.format(i)
            if len(field) > field_lens[key]:
                field_lens[key] = len(field)

    # Print data
    print()
    for fields in linedata:
        print("{:{len_0}}{:{len_1}}  {:{len_2}}{:{len_3}}  {:>{len_4}}  {:>{len_5}}  {:>{len_6}} -> {:{len_7}}".format(
                *fields, **field_lens))

    # Print summary of the diffs
    total1 = sum_vals(bs1)
    total2 = sum_vals(bs2)
    print("\nCumulative {}:".format(val_type))
    print ("  {}    {:+.1f}%    {} ({}) -> {} ({})".format(
                val_to_str(total2 - total1), 100 * (total2-total1) / total1,
                val_to_str(total1, True), val_to_str(total1),
                val_to_str(total2, True), val_to_str(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)

    min_val_defaults = {'cputime': 3.0,
                        'read_bytes': 524288,
                        'write_bytes': 524288}
    min_absdiff_defaults = {'cputime': 1.0,
                            'read_bytes': 131072,
                            'write_bytes': 131072}

    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('--diff-attr', default='cputime',
                        choices=('cputime', 'read_bytes', 'write_bytes'),
                        help="Buildstat attribute which to compare")
    parser.add_argument('--min-val', default=min_val_defaults, type=float,
                        help="Filter out tasks less than MIN_VAL. "
                             "Default depends on --diff-attr.")
    parser.add_argument('--min-absdiff', default=min_absdiff_defaults, type=float,
                        help="Filter out tasks whose difference is less than "
                             "MIN_ABSDIFF, Default depends on --diff-attr.")
    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")

    args = parser.parse_args(argv)

    # Handle defaults for the filter arguments
    if args.min_val is min_val_defaults:
        args.min_val = min_val_defaults[args.diff_attr]
    if args.min_absdiff is min_absdiff_defaults:
        args.min_absdiff = min_absdiff_defaults[args.diff_attr]

    return args


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.diff_attr, args.min_val,
                        args.min_absdiff, sort_by)

    return 0

if __name__ == "__main__":
    sys.exit(main())