1#! /usr/bin/python 2 3# The tool gathers the time used by special tasks/test jobs to a tab-separated 4# output. 5# Import the output to google spreadsheet can generate a sheet like this: 6# https://docs.google.com/a/google.com/spreadsheets/d/ 7# 1iLPSRAgSVz9rGVusTb2yaHJ88iv0QY3hZI_ZI-RdatI/edit#gid=51630294 8 9 10import os 11import argparse 12from datetime import datetime 13import re 14import subprocess 15import sys 16import urllib2 17 18import common 19from autotest_lib.client.common_lib import global_config 20from autotest_lib.frontend import setup_django_environment 21from autotest_lib.frontend.afe import models 22from autotest_lib.frontend.tko import models as tko_models 23from autotest_lib.server.cros.dynamic_suite import job_status 24 25 26CONFIG = global_config.global_config 27AUTOTEST_SERVER = CONFIG.get_config_value('SERVER', 'hostname', type=str) 28 29LOG_BASE_URL = 'http://%s/tko/retrieve_logs.cgi?job=/results/' % AUTOTEST_SERVER 30JOB_URL = LOG_BASE_URL + '%(job_id)s-%(owner)s/%(hostname)s' 31LOG_PATH_FMT = 'hosts/%(hostname)s/%(task_id)d-%(taskname)s' 32TASK_URL = LOG_BASE_URL + LOG_PATH_FMT 33AUTOSERV_DEBUG_LOG = 'debug/autoserv.DEBUG' 34HYPERLINK = '=HYPERLINK("%s","%0.1f")' 35 36GS_URI = 'gs://chromeos-autotest-results' 37 38# A cache of special tasks, hostname:[task] 39tasks_cache = {} 40 41def get_debug_log(autoserv_log_url, autoserv_log_path): 42 """Get a list of strings or a stream for autoserv.DEBUG log file. 43 44 @param autoserv_log_url: Url to the repair job's autoserv.DEBUG log. 45 @param autoserv_log_path: Path to autoserv.DEBUG log, e.g., 46 hosts/hostname/job_id-repair/debug/autoserv.DEBUG. 47 @return: A list of string if debug log was moved to GS already, or a 48 stream of the autoserv.DEBUG file. 49 """ 50 url = urllib2.urlopen(autoserv_log_url).geturl() 51 if not 'accounts.google.com' in url: 52 return urllib2.urlopen(url) 53 else: 54 # The file was moved to Google storage already, read the file from GS. 55 debug_log_link = '%s/%s' % (GS_URI, autoserv_log_path) 56 cmd = 'gsutil cat %s' % debug_log_link 57 proc = subprocess.Popen(cmd, shell=True, stdout=subprocess.PIPE, 58 stderr=subprocess.PIPE) 59 stdout, stderr = proc.communicate() 60 if proc.returncode == 0: 61 return stdout.split(os.linesep) 62 else: 63 print 'Failed to read %s: %s' % (debug_log_link, stderr) 64 65 66class task_runtime(object): 67 """Details about the task run time. 68 """ 69 def __init__(self, task): 70 """Init task_runtime 71 """ 72 # Special task ID 73 self.id = task.id 74 # AFE special_task model 75 self.task = task 76 self.hostname = task.host.hostname 77 78 # Link to log 79 task_info = {'task_id': task.id, 'taskname': task.task.lower(), 80 'hostname': self.hostname} 81 self.log = TASK_URL % task_info 82 83 autoserv_log_url = '%s/%s' % (self.log, AUTOSERV_DEBUG_LOG) 84 log_path = LOG_PATH_FMT % task_info 85 autoserv_log_path = '%s/%s' % (log_path, AUTOSERV_DEBUG_LOG) 86 debug_log = get_debug_log(autoserv_log_url, autoserv_log_path) 87 lines = [line for line in debug_log if line] 88 # Task start time 89 self.start_time = _get_timestamp(lines[0]) 90 # Task end time 91 self.end_time = _get_timestamp(lines[-1]) 92 # Run time across end of a year. 93 if self.end_time < self.start_time: 94 self.end_time = self.end_time.replace(year=self.end_time.year+1) 95 self.time_used = self.end_time - self.start_time 96 97 # Start/end time from afe_special_tasks table. 98 # To support old special tasks, the value falls back to the ones from 99 # debug log. 100 self.start_time_db = (self.task.time_started if self.task.time_started 101 else self.start_time) 102 self.end_time_db = (self.task.time_finished if self.task.time_finished 103 else self.end_time) 104 self.time_used_db = self.end_time_db - self.start_time_db 105 106 107class job_runtime(object): 108 """Details about the job run time, including time spent on special tasks. 109 """ 110 def __init__(self, job, suite_start_time=None, suite_end_time=None): 111 """Init job_run_time 112 """ 113 # AFE job ID 114 self.id = job.id 115 # AFE job model 116 self.job = job 117 # Name of the job, strip all build and suite info. 118 self.name = job.name.split('/')[-1] 119 120 try: 121 self.tko_job = tko_models.Job.objects.filter(afe_job_id=self.id)[0] 122 self.host_id = self.tko_job.machine_id 123 self.hostname = self.tko_job.machine.hostname 124 # Job start time 125 self.start_time = self.tko_job.started_time 126 # Job end time 127 self.end_time = self.tko_job.finished_time 128 self.time_used = self.end_time - self.start_time 129 except IndexError: 130 self.tko_job = None 131 self.host_id = 0 132 self.time_used = 0 133 134 # Link to log 135 self.log = JOB_URL % {'job_id': job.id, 'owner': job.owner, 136 'hostname': self.hostname} 137 138 # Special tasks run before job starts. 139 self.tasks_before = [] 140 # Special tasks run after job finished. 141 self.tasks_after = [] 142 143 # If job time used is not calculated, skip locating special tasks. 144 if not self.time_used: 145 return 146 147 # suite job has no special tasks 148 if not self.hostname: 149 return 150 151 tasks = tasks_cache.get(self.hostname, None) 152 if not tasks: 153 tasks = models.SpecialTask.objects.filter( 154 host__hostname=self.hostname, 155 time_started__gte=suite_start_time, 156 time_started__lte=suite_end_time) 157 tasks_cache[self.hostname] = tasks 158 for task in tasks: 159 if not task.queue_entry or task.queue_entry.job_id != self.id: 160 continue 161 t_runtime = task_runtime(task) 162 if task.time_started < self.start_time: 163 self.tasks_before.append(t_runtime) 164 else: 165 self.tasks_after.append(t_runtime) 166 167 168 def get_all_tasks(self): 169 return self.tasks_before + self.tasks_after 170 171 172 def get_first_task_start_time(self): 173 """Get the start time of first task, return test job start time if 174 there is no tasks_before 175 """ 176 start = self.start_time 177 for task in self.tasks_before: 178 if task.start_time_db < start: 179 start = task.start_time_db 180 return start 181 182 183 def get_last_task_end_time(self): 184 """Get the end time of last task, return test job end time if there is 185 no tasks_after. 186 """ 187 end = self.end_time 188 for task in self.tasks_after: 189 if end < task.end_time_db: 190 end = task.end_time_db 191 return end 192 193 194 def get_total_time(self): 195 return (self.get_last_task_end_time() - 196 self.get_first_task_start_time()).total_seconds() 197 198 199 def get_time_on_tasks(self): 200 time = 0 201 for task in self.tasks_before + self.tasks_after: 202 time += task.time_used.total_seconds() 203 return time 204 205 206 def get_time_on_tasks_from_db(self): 207 time = 0 208 for task in self.tasks_before + self.tasks_after: 209 time += task.time_used_db.total_seconds() 210 return time 211 212 213 def get_time_on_wait(self): 214 return (self.get_total_time() - 215 self.get_time_on_tasks() - 216 self.time_used.total_seconds()) 217 218 219 def get_time_on_wait_from_db(self): 220 return (self.get_total_time() - 221 self.get_time_on_tasks_from_db() - 222 self.time_used.total_seconds()) 223 224 225 def get_time_per_task_type(self, task_type): 226 """only used for suite job 227 """ 228 tasks = [] 229 for job in self.test_jobs: 230 tasks += [task for task in job.get_all_tasks() 231 if task.task.task == task_type] 232 if not tasks: 233 return None 234 235 task_min = tasks[0] 236 task_max = tasks[0] 237 total = 0 238 for task in tasks: 239 if task.time_used < task_min.time_used: 240 task_min = task 241 if task.time_used > task_max.time_used: 242 task_max = task 243 total += task.time_used.total_seconds() 244 return (task_min, task_max, total/len(tasks), len(tasks)) 245 246 247 def get_time_per_task_type_from_db(self, task_type): 248 """only used for suite job 249 """ 250 tasks = [] 251 for job in self.test_jobs: 252 tasks += [task for task in job.get_all_tasks() 253 if task.task.task == task_type] 254 if not tasks: 255 return None 256 257 task_min = tasks[0] 258 task_max = tasks[0] 259 total = 0 260 for task in tasks: 261 if task.time_used_db < task_min.time_used_db: 262 task_min = task 263 if task.time_used_db > task_max.time_used_db: 264 task_max = task 265 total += task.time_used_db.total_seconds() 266 return (task_min, task_max, total/len(tasks), len(tasks)) 267 268 269def _get_timestamp(line): 270 """Get the time from the beginning of a log entry. 271 272 @param line: A line of log entry, e.g., "06/19 19:56:53.602 INFO |" 273 @return: A datetime value of the log entry. 274 """ 275 try: 276 time = re.match( '^(\d\d\/\d\d \d\d:\d\d:\d\d.\d+).*', line).group(1) 277 time = '%d/%s' % (datetime.now().year, time) 278 return datetime.strptime(time, '%Y/%m/%d %H:%M:%S.%f') 279 except: 280 return None 281 282 283def _parse_args(args): 284 if not args: 285 print 'Try ./contrib/compare_suite.py --jobs 51,52,53' 286 sys.exit(0) 287 parser = argparse.ArgumentParser( 288 description=('A script to compare the performance of multiple suite' 289 ' runs.')) 290 parser.add_argument('--jobs', 291 help='A list of job IDs.') 292 return parser.parse_args(args) 293 294 295def merge_time_dict(time_dict_list): 296 merged = {} 297 for time_dict in time_dict_list: 298 for key,val in time_dict.items(): 299 time_used = merged.get(key, 0) 300 merged[key] = time_used + val 301 return merged 302 303 304def print_task_data(all_jobs, time_data): 305 percent_string = delimiter.join( 306 [str(100.0*data[2]*data[3]/suite_job.total_time) 307 if data else '_' for (data, suite_job) in 308 zip(time_data, all_jobs.keys())]) 309 print '%% on %s %s%s' % (task_type, delimiter, percent_string) 310 min_string = delimiter.join( 311 [(HYPERLINK % (data[0].log, data[0].time_used.total_seconds())) 312 if data else '_' for data in time_data]) 313 print ' %s min (seconds)%s%s' % (task_type, delimiter, min_string) 314 max_string = delimiter.join( 315 [HYPERLINK % (data[1].log, data[1].time_used.total_seconds()) 316 if data else '_' for data in time_data]) 317 print ' %s max (seconds)%s%s' % (task_type, delimiter, max_string) 318 ave_string = delimiter.join( 319 [str(data[2]) if data else '_' for data in time_data]) 320 print ' %s average (seconds)%s%s' % (task_type, delimiter, ave_string) 321 322 323if __name__ == '__main__': 324 args = _parse_args(sys.argv[1:]) 325 print 'Comparing jobs: %s' % args.jobs 326 job_ids = [int(id) for id in args.jobs.split(',')] 327 328 # Make sure all jobs are suite jobs 329 parent_jobs = [job.parent_job_id for job in 330 models.Job.objects.filter(id__in=job_ids)] 331 if any(parent_jobs): 332 print ('Some jobs are not suite job. Please provide a list of suite job' 333 ' IDs.') 334 sys.exit(1) 335 336 # A dictionary of suite_job_runtime:{test_job_name:test_job_runtime} 337 all_jobs = {} 338 for job_id in job_ids: 339 suite_job = models.Job.objects.filter(id=job_id)[0] 340 suite_job_runtime = job_runtime(suite_job) 341 test_jobs = models.Job.objects.filter(parent_job_id=job_id) 342 if len(test_jobs) == 0: 343 print 'No child job found for suite job: %d' % job_id 344 sys.exit(1) 345 test_job_runtimes = [job_runtime(job, suite_job_runtime.start_time, 346 suite_job_runtime.end_time) 347 for job in test_jobs] 348 suite_job_runtime.test_jobs = test_job_runtimes 349 suite_job_runtime.hosts = set([job.host_id 350 for job in test_job_runtimes 351 if job.host_id != 0]) 352 suite_job_runtime.total_time = sum( 353 [job.get_total_time() for job in test_job_runtimes]) 354 suite_job_runtime.total_time_on_tasks = sum( 355 [job.get_time_on_tasks() for job in test_job_runtimes]) 356 suite_job_runtime.total_time_on_tasks_from_db = sum( 357 [job.get_time_on_tasks_from_db() for job in test_job_runtimes]) 358 suite_job_runtime.total_time_on_wait = sum( 359 [job.get_time_on_wait() for job in test_job_runtimes]) 360 suite_job_runtime.total_time_on_wait_from_db = sum( 361 [job.get_time_on_wait_from_db() for job in test_job_runtimes]) 362 suite_job_runtime.percent_on_tasks = 100*( 363 suite_job_runtime.total_time_on_tasks / 364 suite_job_runtime.total_time) 365 suite_job_runtime.percent_on_wait = 100*( 366 suite_job_runtime.total_time_on_wait / 367 suite_job_runtime.total_time) 368 suite_job_runtime.percent_on_tasks_from_db = 100*( 369 suite_job_runtime.total_time_on_tasks_from_db / 370 suite_job_runtime.total_time) 371 suite_job_runtime.percent_on_wait_from_db = 100*( 372 suite_job_runtime.total_time_on_wait_from_db / 373 suite_job_runtime.total_time) 374 all_jobs[suite_job_runtime] = {r.name:r for r in test_job_runtimes} 375 376 delimiter = '\t' 377 # Print a row of suite job IDs. 378 print ('job ID%s' % delimiter + 379 delimiter.join([str(suite_job.id) 380 for suite_job in all_jobs.keys()])) 381 382 # Print a row of platforms, e.g., lumpy-release. 383 print ('platform%s' % delimiter + 384 delimiter.join([suite_job.job.name.split('/')[0] 385 for suite_job in all_jobs.keys()])) 386 387 # Print time to run suite 388 print ('time(mins)%s' % delimiter + 389 delimiter.join([str(suite_job.time_used.total_seconds()/60) 390 for suite_job in all_jobs.keys()])) 391 392 # Print percent of time on tasks 393 print ('%% on special tasks%s' % delimiter + 394 delimiter.join([str(suite_job.percent_on_tasks) 395 for suite_job in all_jobs.keys()])) 396 397 # Print percent of time on tasks based on time data from afe_special_tasks 398 print ('%% on special tasks with data from DB%s' % delimiter + 399 delimiter.join([str(suite_job.percent_on_tasks_from_db) 400 for suite_job in all_jobs.keys()])) 401 402 # Print percent of time on tasks per task type 403 all_task_types = set() 404 for suite_job in all_jobs.keys(): 405 for job in suite_job.test_jobs: 406 all_task_types.update( 407 [task.task.task for task in job.get_all_tasks()]) 408 for task_type in all_task_types: 409 print 'Time data retrieved from debug log.' 410 time_data = [suite_job.get_time_per_task_type(task_type) 411 for suite_job in all_jobs.keys()] 412 print_task_data(all_jobs, time_data) 413 414 print 'Time data retrieved from database' 415 time_data = [suite_job.get_time_per_task_type_from_db(task_type) 416 for suite_job in all_jobs.keys()] 417 print_task_data(all_jobs, time_data) 418 419 count_string = delimiter.join( 420 [str(data[3]) if data else '_' for data in time_data]) 421 print ' %s count%s%s' % (task_type, delimiter, count_string) 422 423 # Print percent of time on wait 424 print ('%% on wait%s' % delimiter + 425 delimiter.join([str(suite_job.percent_on_wait) 426 for suite_job in all_jobs.keys()])) 427 428 # Print percent of time on wait based on special task time data from 429 # database 430 print ('%% on wait based on time data from db%s' % delimiter + 431 delimiter.join([str(suite_job.percent_on_wait_from_db) 432 for suite_job in all_jobs.keys()])) 433 434 # Print the number of duts used for suite. 435 print ('dut #%s' % delimiter + 436 delimiter.join([str(len(suite_job.hosts)) 437 for suite_job in all_jobs.keys()])) 438 439 for test_name in [job for job in all_jobs.values()[0].keys()]: 440 line = '%s%s' % (test_name, delimiter) 441 for suite_job in all_jobs.keys(): 442 test_job = all_jobs[suite_job].get(test_name) 443 if test_job: 444 line += (HYPERLINK % 445 (test_job.log, test_job.time_used.total_seconds()) 446 + delimiter) 447 else: 448 line += '_%s' % delimiter 449 print line 450