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