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