| #! /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 |
