diff -r 0e65f93be3cb -r ac0bbc1e5d79 sbsv2/raptor/bin/grokbuild.py --- /dev/null Thu Jan 01 00:00:00 1970 +0000 +++ b/sbsv2/raptor/bin/grokbuild.py Mon Sep 13 13:11:19 2010 +0800 @@ -0,0 +1,324 @@ +#!/usr/bin/env python +# +# Copyright (c) 2010 Nokia Corporation and/or its subsidiary(-ies). +# All rights reserved. +# This component and the accompanying materials are made available +# under the terms of the License "Eclipse Public License v1.0" +# which accompanies this distribution, and is available +# at the URL "http://www.eclipse.org/legal/epl-v10.html". +# +# Initial Contributors: +# Nokia Corporation - initial contribution. +# +# Contributors: +# +# Description: +# grokbuild +# + +""" +Gathers performance metrics from the logs of a complex multi-step build. +Supports Helium 9 at the moment but is adaptable. + +Can read from emake annotation files. +""" + +import sys +import os +import re +from optparse import OptionParser +import annofile +import datetime + + +class UndeterminedBuildID(Exception): + pass + +class LogfileNotFound(Exception): + pass + +class HeliumLog(object): + """ Some common properties of any log file in a helium build """ + filenamesuffix = None + + def __init__(self, logpath, buildid, options=None): + + self.logfilename = os.path.join(logpath, buildid + self.filenamesuffix) + self.buildid = buildid + self.options = options + + @classmethod + def findall(c, logpath): + """ Find all the logs that are of this type - essentially also finds all builds + which dumped their output in the same place """ + filename_re = re.compile('(.*/)?(?P[^\\\/]*)' + c.filenamesuffix) + logs = {} + for f in os.listdir(logpath): + m = filename_re.match(f) + if m: + file_buildid = m.groupdict()['buildid'] + logs[file_buildid] = os.path.join(logpath,f) + return logs + + + def __str__(self): + return "\n" % self.buildid + +class MainAntLog(HeliumLog): + """ This is the primary log of the helium build. Useful for obtaining the total build time. Not good for this if the build failed. """ + # output/logs/92_7952_201020_003_main.ant.log + filenamesuffix = "_main.ant.log" + timeformat = "%Y/%m/%d %H:%M:%S:%f" # e.g. Thu 2010/06/24 09:15:42:625 AM + + def __init__(self, logpath, buildid, options=None): + super(MainAntLog,self).__init__(logpath, buildid, options) + + # Starting logging into y:\output\logs\mcl_7901_201024_20100623181534_main.ant.log at Wed 2010/06/23 21:16:12:972 PM + # Stopping logging into y:\output\logs\mcl_7901_201024_20100623181534_main.ant.log from hlm:record task at Thu 2010/06/24 09:15:42:625 AM + + start_re = re.compile("Starting logging into [^ ]+ at ... ([^ ]+ +[^ ]+) .*") + stop_re = re.compile("Stopping logging into [^ ]+ from [^ ]+ task at ... ([^ ]+ +[^ ]+) (AM)|(PM).*") + start_time = None + stop_time = None + with open(self.logfilename) as f: + for l in f: + if start_time is None: + m = start_re.match(l) + if m: + #sys.stderr.write("start TIME: %s\n" %m.groups()[0]) + start_time = datetime.datetime.strptime(m.groups()[0], self.timeformat) + + else: # if there are many stop lines then make sure the last one overrides the others + m = stop_re.match(l) + if m: + stop_time = datetime.datetime.strptime(m.groups()[0], self.timeformat) + #sys.stderr.write("stop TIME: %s\n" %m.groups()[0]) + + #sys.stderr.write("build start/stop: %s / %s from %s\n" % (start_time, stop_time, self.logfilename)) + build_duration = stop_time - start_time # returns a timedelta object + self.build_duration = build_duration.seconds + 86400 * build_duration.days # seconds + + def __str__(self): + return "\n" % self.build_duration + +class AntEnvLog(HeliumLog): + # output/logs/92_7952_201020_003_ant_env.log + filenamesuffix = "_ant_env.log" + + def __init__(self, logpath, buildid): + super(AntEnvLog,self).__init__(logpath, buildid) + +class TargetTimesLog(HeliumLog): + """Very useful timing data from Ant but does not get created in all builds by default (must be configured""" + # output/logs/92_7952_custom_dilbert_201022_dilbert_targetTimesLog.csv + filenamesuffix = "_targetTimesLog.csv" + + def __init__(self, logpath, buildid): + super(TargetTimesLog,self).__init__(logpath, buildid) + self.raptorsecs = 0 + self.totalsecs = 0 + + with open(self.logfilename) as f: + for ll in f: + l = ll.rstrip("\n") + #print self.logfilename + #print "L:",l + (rname, rsecs) = l.split(",") + rsecs = int(rsecs) + #print "rname, rsecs: %s %d"%(rname,rsecs) + self.totalsecs += rsecs + if rname == "compile-sbs": + self.raptorsecs += rsecs + + def __str__(self): + s = "" % self.totalsecs \ + + "\n\n" % self.raptorsecs + return s + +class RaptorAnnofile(object): + """Thin wrapper around the annofile class to make it relevant to this utility.""" + # Examples: + # 92_7952_custom_dilbert_201022_dilbert_dfs_build_sf_tools_all.resource.emake.anno + # 92_7952_custom_dilbert_201022_dilbert_dfs_build_sf_dfs_variants.default.emake.anno + # 92_7952_201022_003_dfs_build_ncp_dfs_variants.resource_deps.emake.anno + def __init__(self, filename, buildid, maxagents): + self.phase = "" + self.filename = filename + self.buildid = buildid + + self.annofile = annofile.Annofile(self.filename, maxagents) + + def __str__(self): + return "\n%s\n" \ + % (os.path.basename(self.filename), self.phase, str(self.annofile)) + + +class RaptorBuild(HeliumLog): + """Any Raptor logfile. Mainly used for getting the names of the + annotation files which the annofile parser will use. Also gets + the version of raptor and the total time taken by this particular + invocation of Raptor""" + def __init__(self, logpath, buildid, build, options=None): + self.filenamesuffix = '_%s' % build + super(RaptorBuild,self).__init__(os.path.join(logpath, "compile"), buildid, options) + self.build = build + + if not os.path.isfile(self.logfilename): + raise LogfileNotFound("missing log file: %s\n" % self.logfilename) + + self.annofile_refs = [] + self.build_duration = None + + status_re = re.compile("Executing.*--emake-annofile=([^ ]+)") + emake_maxagents_re = re.compile("--emake-maxagents=(\d+)") + sbs_version_re = re.compile("sbs: version ([^\n\r]*)") + run_time_re = re.compile("Run time ([0-9]+) seconds") + + self.recipes = { 'TOTAL':0, 'ok':0, 'failed':0, 'retry':0 } + + with open(self.logfilename) as f: + sys.stderr.write(" parsing build log %s\n" % os.path.split(self.logfilename)[1]) + for l in f: + # match in order of likelihood (most probable first) + + m = status_re.match(l) + if m: + self.recipes['TOTAL'] += 1 + status = m.group(1) + try: + self.recipes[status] += 1 + except KeyError: + sys.stderr.write("unknown recipe status '%s'" % status) + continue + + m = emake_invocation_re.match(l) + if m: + (adir, aname) = os.path.split(m.group(1)) + if aname.find("pp")==-1: # no parallel parsing ones preferably + sys.stderr.write(" found annotation file %s\n" % aname) + + # if --emake-maxagents is present then use that, otherwise use + # the value passed in through the options. + m = emake_maxagents_re.match(l) + if m: + maxagents = int(m.group(1)) + else: + maxagents = options.maxagents + sys.stderr.write(" using maxagents %d as there is no record in the logs\n" % maxagents) + + self.annofile_refs.append( (os.path.join(logpath, "makefile", aname), maxagents) ) + continue + + m = run_time_re.match(l) + if m: + self.build_duration = int(m.group(1)) + continue + + m = sbs_version_re.match(l) + if m: + self.version = m.group(1) + + self.annofiles = [] + for p in self.annofile_refs: + self.annofiles.append(RaptorAnnofile(p[0], buildid, p[1])) + + def __str__(self): + recipes = [" \n" % x for x in self.recipes.items()] + + return "\n" % os.path.split(self.logfilename)[-1] + \ + " \n" % (self.version) + \ + " \n" % (self.build, self.build_duration) + \ + "".join(recipes) + \ + "".join([str(a) for a in self.annofiles]) + \ + "\n" + + + +class HeliumBuild(object): + """A build with any version of Helium""" + def __init__(self, logpath, buildid, options=None): + self.options = options + self.buildid = buildid + self.logpath = logpath + self.logfiles=[] + + def __str__(self): + return self.buildid + \ + "\n"+[str(a) for a in self.annofiles] + "\n" + +class Helium9Build(HeliumBuild): + """ Filenames, structure etc conform to Helium 9 """ + def __init__(self, logpath, buildid, options=None): + super(Helium9Build,self).__init__(logpath, buildid, options) + self.mainantlog = MainAntLog(logpath, buildid, options) + self.raptorbuilds = [] + + # mcl_7901_201024_20100623181534_dfs_build_ncp_variants.build_input_compile.log + # mcl_7901_201024_20100623181534_dfs_build_sf_variants.build_input_compile.log + # mcl_7901_201024_20100623181534_dfs_build_winscw_dfs_build_winscw_input_compile.log + # + # ....but the problem is that the anno files have a slightly differing convention: + # 92_7952_201022_003_dfs_build_ncp_dfs_variants.resource_deps.emake.anno + # _dfs_build_ncp_variants + # _dfs_build_ncp_dfs_variants + # read the annofile names from inside the raptor log output + for r in ["dfs_build_ncp_variants.build_input_compile.log","dfs_build_sf_variants.build_input_compile.log","dfs_build_winscw_dfs_build_winscw_input_compile.log", "ncp_symbian_build_symtb_input_compile.log"]: + try: + self.raptorbuilds.append(RaptorBuild(logpath, buildid, r, options)) + except LogfileNotFound, ex: + sys.stderr.write(str(ex)) + + def __str__(self): + + raptor_duration = reduce(lambda x, y: x + y,[y.build_duration for y in self.raptorbuilds],0) + return "\n" % (self.buildid) + \ + "\n" % (self.mainantlog.build_duration) + \ + "\n" % (raptor_duration) + \ + "".join([str(a) for a in self.raptorbuilds ]) + \ + "\n" + + +class HeliumLogDir(object): + """Multiple builds can be done one after another (usually when rebuilding + things that failed, apparently) and their logs left in the output dir. + The naming convention ensures that they don't overwrite each other. + This class identifies each build and tries to analyse them one by one.""" + def __init__(self, epocroot, options=None): + self.logpath = os.path.join(epocroot, "output/logs") + logs = MainAntLog.findall(self.logpath) + self.builds = [] + + for b in logs.keys(): + try: + sys.stderr.write(" Found build with id %s\n" % b) + build = Helium9Build(self.logpath, b, options) + self.builds.append(build) + except IOError,e: + sys.stderr.write(" Buildid %s found but does not refer to a complete build\n" % b) + sys.stderr.write(str(e)+"\n") + + def write(self, stream): + for b in self.builds: + stream.write(str(b)+"\n") + + +parser = OptionParser(prog = "grokbuild", + usage = """%prog [-h | options] path_to_EPOCROOT + +The build logs are usually in $EPOCROOT/output/logs""") + +parser.add_option("--maxagents", type="int", dest="maxagents", default=30, + help="The number of simultaneous agents used in the build. You need to supply this if --emake-class was used rather than --emake-maxagents since this is then a property of the build cluster and is not usually recorded in the logs. The default is %default." + ) +(options, args) = parser.parse_args() + +if len(args) == 0: + sys.stderr.write("Need at least one argument: a path to the logs.\n") + sys.exit(-1) + +epocroot = args[0] +sys.stderr.write("Gathering Performance Metrics for %s\n" % epocroot) + +b = HeliumLogDir(epocroot, options) +b.write(sys.stdout)