contrib/compare_suite.py

#! /usr/bin/python

# The tool gathers the time used by special tasks/test jobs to a tab-separated
# output.
# Import the output to google spreadsheet can generate a sheet like this:
# https://docs.google.com/a/google.com/spreadsheets/d/
# 1iLPSRAgSVz9rGVusTb2yaHJ88iv0QY3hZI_ZI-RdatI/edit#gid=51630294


import os
import argparse
from datetime import datetime
import re
import subprocess
import sys
import urllib2

import common
from autotest_lib.client.common_lib import global_config
from autotest_lib.frontend import setup_django_environment
from autotest_lib.frontend.afe import models
from autotest_lib.frontend.tko import models as tko_models
from autotest_lib.server.cros.dynamic_suite import job_status


CONFIG = global_config.global_config
AUTOTEST_SERVER = CONFIG.get_config_value('SERVER', 'hostname', type=str)

LOG_BASE_URL = 'http://%s/tko/retrieve_logs.cgi?job=/results/' % AUTOTEST_SERVER
JOB_URL = LOG_BASE_URL + '%(job_id)s-%(owner)s/%(hostname)s'
LOG_PATH_FMT = 'hosts/%(hostname)s/%(task_id)d-%(taskname)s'
TASK_URL = LOG_BASE_URL + LOG_PATH_FMT
AUTOSERV_DEBUG_LOG = 'debug/autoserv.DEBUG'
HYPERLINK = '=HYPERLINK("%s","%0.1f")'

GS_URI =  'gs://chromeos-autotest-results'

# A cache of special tasks, hostname:[task]
tasks_cache = {}

def get_debug_log(autoserv_log_url, autoserv_log_path):
    """Get a list of strings or a stream for autoserv.DEBUG log file.

    @param autoserv_log_url: Url to the repair job's autoserv.DEBUG log.
    @param autoserv_log_path: Path to autoserv.DEBUG log, e.g.,
                        hosts/hostname/job_id-repair/debug/autoserv.DEBUG.
    @return: A list of string if debug log was moved to GS already, or a
             stream of the autoserv.DEBUG file.
    """
    url = urllib2.urlopen(autoserv_log_url).geturl()
    if not 'accounts.google.com' in url:
        return urllib2.urlopen(url)
    else:
        # The file was moved to Google storage already, read the file from GS.
        debug_log_link = '%s/%s' % (GS_URI, autoserv_log_path)
        cmd = 'gsutil cat %s' % debug_log_link
        proc = subprocess.Popen(cmd, shell=True, stdout=subprocess.PIPE,
                                stderr=subprocess.PIPE)
        stdout, stderr = proc.communicate()
        if proc.returncode == 0:
            return stdout.split(os.linesep)
        else:
            print 'Failed to read %s: %s' % (debug_log_link, stderr)


class task_runtime(object):
    """Details about the task run time.
    """
    def __init__(self, task):
        """Init task_runtime
        """
        # Special task ID
        self.id = task.id
        # AFE special_task model
        self.task = task
        self.hostname = task.host.hostname

        # Link to log
        task_info = {'task_id': task.id, 'taskname': task.task.lower(),
                     'hostname': self.hostname}
        self.log = TASK_URL % task_info

        autoserv_log_url = '%s/%s' % (self.log, AUTOSERV_DEBUG_LOG)
        log_path = LOG_PATH_FMT % task_info
        autoserv_log_path = '%s/%s' % (log_path, AUTOSERV_DEBUG_LOG)
        debug_log = get_debug_log(autoserv_log_url, autoserv_log_path)
        lines = [line for line in debug_log if line]
        # Task start time
        self.start_time = _get_timestamp(lines[0])
        # Task end time
        self.end_time = _get_timestamp(lines[-1])
        # Run time across end of a year.
        if self.end_time < self.start_time:
            self.end_time = self.end_time.replace(year=self.end_time.year+1)
        self.time_used = self.end_time - self.start_time

        # Start/end time from afe_special_tasks table.
        # To support old special tasks, the value falls back to the ones from
        # debug log.
        self.start_time_db = (self.task.time_started if self.task.time_started
                              else self.start_time)
        self.end_time_db = (self.task.time_finished if self.task.time_finished
                            else self.end_time)
        self.time_used_db = self.end_time_db - self.start_time_db


class job_runtime(object):
    """Details about the job run time, including time spent on special tasks.
    """
    def __init__(self, job, suite_start_time=None, suite_end_time=None):
        """Init job_run_time
        """
        # AFE job ID
        self.id = job.id
        # AFE job model
        self.job = job
        # Name of the job, strip all build and suite info.
        self.name = job.name.split('/')[-1]

        try:
            self.tko_job = tko_models.Job.objects.filter(afe_job_id=self.id)[0]
            self.host_id = self.tko_job.machine_id
            self.hostname = self.tko_job.machine.hostname
            # Job start time
            self.start_time = self.tko_job.started_time
            # Job end time
            self.end_time = self.tko_job.finished_time
            self.time_used = self.end_time - self.start_time
        except IndexError:
            self.tko_job = None
            self.host_id = 0
            self.time_used = 0

        # Link to log
        self.log = JOB_URL % {'job_id': job.id, 'owner': job.owner,
                              'hostname': self.hostname}

        # Special tasks run before job starts.
        self.tasks_before = []
        # Special tasks run after job finished.
        self.tasks_after = []

        # If job time used is not calculated, skip locating special tasks.
        if not self.time_used:
            return

        # suite job has no special tasks
        if not self.hostname:
            return

        tasks = tasks_cache.get(self.hostname, None)
        if not tasks:
            tasks = models.SpecialTask.objects.filter(
                    host__hostname=self.hostname,
                    time_started__gte=suite_start_time,
                    time_started__lte=suite_end_time)
            tasks_cache[self.hostname] = tasks
        for task in tasks:
            if not task.queue_entry or task.queue_entry.job_id != self.id:
                continue
            t_runtime = task_runtime(task)
            if task.time_started < self.start_time:
                self.tasks_before.append(t_runtime)
            else:
                self.tasks_after.append(t_runtime)


    def get_all_tasks(self):
        return self.tasks_before + self.tasks_after


    def get_first_task_start_time(self):
        """Get the start time of first task, return test job start time if
        there is no tasks_before
        """
        start = self.start_time
        for task in self.tasks_before:
            if task.start_time_db < start:
                start = task.start_time_db
        return start


    def get_last_task_end_time(self):
        """Get the end time of last task, return test job end time if there is
        no tasks_after.
        """
        end = self.end_time
        for task in self.tasks_after:
            if end < task.end_time_db:
                end = task.end_time_db
        return end


    def get_total_time(self):
        return (self.get_last_task_end_time() -
                self.get_first_task_start_time()).total_seconds()


    def get_time_on_tasks(self):
        time = 0
        for task in self.tasks_before + self.tasks_after:
            time += task.time_used.total_seconds()
        return time


    def get_time_on_tasks_from_db(self):
        time = 0
        for task in self.tasks_before + self.tasks_after:
            time += task.time_used_db.total_seconds()
        return time


    def get_time_on_wait(self):
        return (self.get_total_time() -
                self.get_time_on_tasks() -
                self.time_used.total_seconds())


    def get_time_on_wait_from_db(self):
        return (self.get_total_time() -
                self.get_time_on_tasks_from_db() -
                self.time_used.total_seconds())


    def get_time_per_task_type(self, task_type):
        """only used for suite job
        """
        tasks = []
        for job in self.test_jobs:
            tasks += [task for task in job.get_all_tasks()
                          if task.task.task == task_type]
        if not tasks:
            return None

        task_min = tasks[0]
        task_max = tasks[0]
        total = 0
        for task in tasks:
            if task.time_used < task_min.time_used:
                task_min = task
            if task.time_used > task_max.time_used:
                task_max = task
            total += task.time_used.total_seconds()
        return (task_min, task_max, total/len(tasks), len(tasks))


    def get_time_per_task_type_from_db(self, task_type):
        """only used for suite job
        """
        tasks = []
        for job in self.test_jobs:
            tasks += [task for task in job.get_all_tasks()
                          if task.task.task == task_type]
        if not tasks:
            return None

        task_min = tasks[0]
        task_max = tasks[0]
        total = 0
        for task in tasks:
            if task.time_used_db < task_min.time_used_db:
                task_min = task
            if task.time_used_db > task_max.time_used_db:
                task_max = task
            total += task.time_used_db.total_seconds()
        return (task_min, task_max, total/len(tasks), len(tasks))


def _get_timestamp(line):
    """Get the time from the beginning of a log entry.

    @param line: A line of log entry, e.g., "06/19 19:56:53.602 INFO |"
    @return: A datetime value of the log entry.
    """
    try:
        time = re.match( '^(\d\d\/\d\d \d\d:\d\d:\d\d.\d+).*', line).group(1)
        time = '%d/%s' % (datetime.now().year, time)
        return datetime.strptime(time, '%Y/%m/%d %H:%M:%S.%f')
    except:
        return None


def _parse_args(args):
    if not args:
        print 'Try ./contrib/compare_suite.py --jobs 51,52,53'
        sys.exit(0)
    parser = argparse.ArgumentParser(
            description=('A script to compare the performance of multiple suite'
                         ' runs.'))
    parser.add_argument('--jobs',
                        help='A list of job IDs.')
    return parser.parse_args(args)


def merge_time_dict(time_dict_list):
    merged = {}
    for time_dict in time_dict_list:
        for key,val in time_dict.items():
            time_used = merged.get(key, 0)
            merged[key] = time_used + val
    return merged


def print_task_data(all_jobs, time_data):
    percent_string = delimiter.join(
            [str(100.0*data[2]*data[3]/suite_job.total_time)
             if data else '_' for (data, suite_job) in
             zip(time_data, all_jobs.keys())])
    print '%% on %s %s%s' % (task_type, delimiter, percent_string)
    min_string = delimiter.join(
            [(HYPERLINK % (data[0].log, data[0].time_used.total_seconds()))
             if data else '_' for data in time_data])
    print '  %s min (seconds)%s%s' % (task_type, delimiter, min_string)
    max_string = delimiter.join(
            [HYPERLINK % (data[1].log, data[1].time_used.total_seconds())
             if data else '_' for data in time_data])
    print '  %s max (seconds)%s%s' % (task_type, delimiter, max_string)
    ave_string = delimiter.join(
            [str(data[2]) if data else '_' for data in time_data])
    print '  %s average (seconds)%s%s' % (task_type, delimiter, ave_string)


if __name__ == '__main__':
    args = _parse_args(sys.argv[1:])
    print 'Comparing jobs: %s' % args.jobs
    job_ids = [int(id) for id in args.jobs.split(',')]

    # Make sure all jobs are suite jobs
    parent_jobs = [job.parent_job_id for job in
                   models.Job.objects.filter(id__in=job_ids)]
    if any(parent_jobs):
        print ('Some jobs are not suite job. Please provide a list of suite job'
               ' IDs.')
        sys.exit(1)

    # A dictionary of suite_job_runtime:{test_job_name:test_job_runtime}
    all_jobs = {}
    for job_id in job_ids:
        suite_job = models.Job.objects.filter(id=job_id)[0]
        suite_job_runtime = job_runtime(suite_job)
        test_jobs = models.Job.objects.filter(parent_job_id=job_id)
        if len(test_jobs) == 0:
            print 'No child job found for suite job: %d' % job_id
            sys.exit(1)
        test_job_runtimes = [job_runtime(job, suite_job_runtime.start_time,
                                         suite_job_runtime.end_time)
                             for job in test_jobs]
        suite_job_runtime.test_jobs = test_job_runtimes
        suite_job_runtime.hosts = set([job.host_id
                                       for job in test_job_runtimes
                                       if job.host_id != 0])
        suite_job_runtime.total_time = sum(
                [job.get_total_time() for job in test_job_runtimes])
        suite_job_runtime.total_time_on_tasks = sum(
                [job.get_time_on_tasks() for job in test_job_runtimes])
        suite_job_runtime.total_time_on_tasks_from_db = sum(
                [job.get_time_on_tasks_from_db() for job in test_job_runtimes])
        suite_job_runtime.total_time_on_wait = sum(
                [job.get_time_on_wait() for job in test_job_runtimes])
        suite_job_runtime.total_time_on_wait_from_db = sum(
                [job.get_time_on_wait_from_db() for job in test_job_runtimes])
        suite_job_runtime.percent_on_tasks = 100*(
                suite_job_runtime.total_time_on_tasks /
                suite_job_runtime.total_time)
        suite_job_runtime.percent_on_wait = 100*(
                suite_job_runtime.total_time_on_wait /
                suite_job_runtime.total_time)
        suite_job_runtime.percent_on_tasks_from_db = 100*(
                suite_job_runtime.total_time_on_tasks_from_db /
                suite_job_runtime.total_time)
        suite_job_runtime.percent_on_wait_from_db = 100*(
                suite_job_runtime.total_time_on_wait_from_db /
                suite_job_runtime.total_time)
        all_jobs[suite_job_runtime] = {r.name:r for r in test_job_runtimes}

    delimiter = '\t'
    # Print a row of suite job IDs.
    print ('job ID%s' % delimiter +
           delimiter.join([str(suite_job.id)
                           for suite_job in all_jobs.keys()]))

    # Print a row of platforms, e.g., lumpy-release.
    print ('platform%s' % delimiter +
           delimiter.join([suite_job.job.name.split('/')[0]
                           for suite_job in all_jobs.keys()]))

    # Print time to run suite
    print ('time(mins)%s' % delimiter +
           delimiter.join([str(suite_job.time_used.total_seconds()/60)
                           for suite_job in all_jobs.keys()]))

    # Print percent of time on tasks
    print ('%% on special tasks%s' % delimiter +
           delimiter.join([str(suite_job.percent_on_tasks)
                           for suite_job in all_jobs.keys()]))

    # Print percent of time on tasks based on time data from afe_special_tasks
    print ('%% on special tasks with data from DB%s' % delimiter +
           delimiter.join([str(suite_job.percent_on_tasks_from_db)
                           for suite_job in all_jobs.keys()]))

    # Print percent of time on tasks per task type
    all_task_types = set()
    for suite_job in all_jobs.keys():
        for job in suite_job.test_jobs:
            all_task_types.update(
                    [task.task.task for task in job.get_all_tasks()])
    for task_type in all_task_types:
        print 'Time data retrieved from debug log.'
        time_data = [suite_job.get_time_per_task_type(task_type)
                     for suite_job in all_jobs.keys()]
        print_task_data(all_jobs, time_data)

        print 'Time data retrieved from database'
        time_data = [suite_job.get_time_per_task_type_from_db(task_type)
                     for suite_job in all_jobs.keys()]
        print_task_data(all_jobs, time_data)

        count_string = delimiter.join(
                [str(data[3]) if data else '_' for data in time_data])
        print '  %s count%s%s' % (task_type, delimiter, count_string)

    # Print percent of time on wait
    print ('%% on wait%s' % delimiter +
           delimiter.join([str(suite_job.percent_on_wait)
                           for suite_job in all_jobs.keys()]))

    # Print percent of time on wait based on special task time data from
    # database
    print ('%% on wait based on time data from db%s' % delimiter +
           delimiter.join([str(suite_job.percent_on_wait_from_db)
                           for suite_job in all_jobs.keys()]))

    # Print the number of duts used for suite.
    print ('dut #%s' % delimiter +
           delimiter.join([str(len(suite_job.hosts))
                           for suite_job in all_jobs.keys()]))

    for test_name in [job for job in all_jobs.values()[0].keys()]:
        line = '%s%s' % (test_name, delimiter)
        for suite_job in all_jobs.keys():
            test_job = all_jobs[suite_job].get(test_name)
            if test_job:
                line += (HYPERLINK %
                         (test_job.log, test_job.time_used.total_seconds())
                         + delimiter)
            else:
                line += '_%s' % delimiter
        print line