|
1 #!/usr/bin/env python |
|
2 # |
|
3 # Copyright (c) 2010 Nokia Corporation and/or its subsidiary(-ies). |
|
4 # All rights reserved. |
|
5 # This component and the accompanying materials are made available |
|
6 # under the terms of the License "Eclipse Public License v1.0" |
|
7 # which accompanies this distribution, and is available |
|
8 # at the URL "http://www.eclipse.org/legal/epl-v10.html". |
|
9 # |
|
10 # Initial Contributors: |
|
11 # Nokia Corporation - initial contribution. |
|
12 # |
|
13 # Contributors: |
|
14 # |
|
15 # Description: |
|
16 # grokbuild |
|
17 # |
|
18 |
|
19 """ |
|
20 Gathers performance metrics from the logs of a complex multi-step build. |
|
21 Supports Helium 9 at the moment but is adaptable. |
|
22 |
|
23 Can read from emake annotation files. |
|
24 """ |
|
25 |
|
26 import sys |
|
27 import os |
|
28 import re |
|
29 from optparse import OptionParser |
|
30 import annofile |
|
31 import datetime |
|
32 |
|
33 |
|
34 class UndeterminedBuildID(Exception): |
|
35 pass |
|
36 |
|
37 class LogfileNotFound(Exception): |
|
38 pass |
|
39 |
|
40 class HeliumLog(object): |
|
41 """ Some common properties of any log file in a helium build """ |
|
42 filenamesuffix = None |
|
43 |
|
44 def __init__(self, logpath, buildid, options=None): |
|
45 |
|
46 self.logfilename = os.path.join(logpath, buildid + self.filenamesuffix) |
|
47 self.buildid = buildid |
|
48 self.options = options |
|
49 |
|
50 @classmethod |
|
51 def findall(c, logpath): |
|
52 """ Find all the logs that are of this type - essentially also finds all builds |
|
53 which dumped their output in the same place """ |
|
54 filename_re = re.compile('(.*/)?(?P<buildid>[^\\\/]*)' + c.filenamesuffix) |
|
55 logs = {} |
|
56 for f in os.listdir(logpath): |
|
57 m = filename_re.match(f) |
|
58 if m: |
|
59 file_buildid = m.groupdict()['buildid'] |
|
60 logs[file_buildid] = os.path.join(logpath,f) |
|
61 return logs |
|
62 |
|
63 |
|
64 def __str__(self): |
|
65 return "<metric name='buildid' value='%s'>\n" % self.buildid |
|
66 |
|
67 class MainAntLog(HeliumLog): |
|
68 """ This is the primary log of the helium build. Useful for obtaining the total build time. Not good for this if the build failed. """ |
|
69 # output/logs/92_7952_201020_003_main.ant.log |
|
70 filenamesuffix = "_main.ant.log" |
|
71 timeformat = "%Y/%m/%d %H:%M:%S:%f" # e.g. Thu 2010/06/24 09:15:42:625 AM |
|
72 |
|
73 def __init__(self, logpath, buildid, options=None): |
|
74 super(MainAntLog,self).__init__(logpath, buildid, options) |
|
75 |
|
76 # Starting logging into y:\output\logs\mcl_7901_201024_20100623181534_main.ant.log at Wed 2010/06/23 21:16:12:972 PM |
|
77 # 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 |
|
78 |
|
79 start_re = re.compile("Starting logging into [^ ]+ at ... ([^ ]+ +[^ ]+) .*") |
|
80 stop_re = re.compile("Stopping logging into [^ ]+ from [^ ]+ task at ... ([^ ]+ +[^ ]+) (AM)|(PM).*") |
|
81 start_time = None |
|
82 stop_time = None |
|
83 with open(self.logfilename) as f: |
|
84 for l in f: |
|
85 if start_time is None: |
|
86 m = start_re.match(l) |
|
87 if m: |
|
88 #sys.stderr.write("start TIME: %s\n" %m.groups()[0]) |
|
89 start_time = datetime.datetime.strptime(m.groups()[0], self.timeformat) |
|
90 |
|
91 else: # if there are many stop lines then make sure the last one overrides the others |
|
92 m = stop_re.match(l) |
|
93 if m: |
|
94 stop_time = datetime.datetime.strptime(m.groups()[0], self.timeformat) |
|
95 #sys.stderr.write("stop TIME: %s\n" %m.groups()[0]) |
|
96 |
|
97 #sys.stderr.write("build start/stop: %s / %s from %s\n" % (start_time, stop_time, self.logfilename)) |
|
98 build_duration = stop_time - start_time # returns a timedelta object |
|
99 self.build_duration = build_duration.seconds + 86400 * build_duration.days # seconds |
|
100 |
|
101 def __str__(self): |
|
102 return "<metric name='build_duration' value='%d'>\n" % self.build_duration |
|
103 |
|
104 class AntEnvLog(HeliumLog): |
|
105 # output/logs/92_7952_201020_003_ant_env.log |
|
106 filenamesuffix = "_ant_env.log" |
|
107 |
|
108 def __init__(self, logpath, buildid): |
|
109 super(AntEnvLog,self).__init__(logpath, buildid) |
|
110 |
|
111 class TargetTimesLog(HeliumLog): |
|
112 """Very useful timing data from Ant but does not get created in all builds by default (must be configured""" |
|
113 # output/logs/92_7952_custom_dilbert_201022_dilbert_targetTimesLog.csv |
|
114 filenamesuffix = "_targetTimesLog.csv" |
|
115 |
|
116 def __init__(self, logpath, buildid): |
|
117 super(TargetTimesLog,self).__init__(logpath, buildid) |
|
118 self.raptorsecs = 0 |
|
119 self.totalsecs = 0 |
|
120 |
|
121 with open(self.logfilename) as f: |
|
122 for ll in f: |
|
123 l = ll.rstrip("\n") |
|
124 #print self.logfilename |
|
125 #print "L:",l |
|
126 (rname, rsecs) = l.split(",") |
|
127 rsecs = int(rsecs) |
|
128 #print "rname, rsecs: %s %d"%(rname,rsecs) |
|
129 self.totalsecs += rsecs |
|
130 if rname == "compile-sbs": |
|
131 self.raptorsecs += rsecs |
|
132 |
|
133 def __str__(self): |
|
134 s = "<metric name='build_duration' value='%s'>" % self.totalsecs \ |
|
135 + "\n<metric name='raptor_duration' value='%s'>\n" % self.raptorsecs |
|
136 return s |
|
137 |
|
138 class RaptorAnnofile(object): |
|
139 """Thin wrapper around the annofile class to make it relevant to this utility.""" |
|
140 # Examples: |
|
141 # 92_7952_custom_dilbert_201022_dilbert_dfs_build_sf_tools_all.resource.emake.anno |
|
142 # 92_7952_custom_dilbert_201022_dilbert_dfs_build_sf_dfs_variants.default.emake.anno |
|
143 # 92_7952_201022_003_dfs_build_ncp_dfs_variants.resource_deps.emake.anno |
|
144 def __init__(self, filename, buildid, maxagents): |
|
145 self.phase = "" |
|
146 self.filename = filename |
|
147 self.buildid = buildid |
|
148 |
|
149 self.annofile = annofile.Annofile(self.filename, maxagents) |
|
150 |
|
151 def __str__(self): |
|
152 return "<annofile name='%s' phase='%s'>\n%s</annofile>\n" \ |
|
153 % (os.path.basename(self.filename), self.phase, str(self.annofile)) |
|
154 |
|
155 |
|
156 class RaptorBuild(HeliumLog): |
|
157 """Any Raptor logfile. Mainly used for getting the names of the |
|
158 annotation files which the annofile parser will use. Also gets |
|
159 the version of raptor and the total time taken by this particular |
|
160 invocation of Raptor""" |
|
161 def __init__(self, logpath, buildid, build, options=None): |
|
162 self.filenamesuffix = '_%s' % build |
|
163 super(RaptorBuild,self).__init__(os.path.join(logpath, "compile"), buildid, options) |
|
164 self.build = build |
|
165 |
|
166 if not os.path.isfile(self.logfilename): |
|
167 raise LogfileNotFound("missing log file: %s\n" % self.logfilename) |
|
168 |
|
169 self.annofile_refs = [] |
|
170 self.build_duration = None |
|
171 |
|
172 status_re = re.compile("<status exit='([a-z]+)'") |
|
173 emake_invocation_re = re.compile("<info>Executing.*--emake-annofile=([^ ]+)") |
|
174 emake_maxagents_re = re.compile("--emake-maxagents=(\d+)") |
|
175 sbs_version_re = re.compile("<info>sbs: version ([^\n\r]*)") |
|
176 run_time_re = re.compile("<info>Run time ([0-9]+) seconds</info>") |
|
177 |
|
178 self.recipes = { 'TOTAL':0, 'ok':0, 'failed':0, 'retry':0 } |
|
179 |
|
180 with open(self.logfilename) as f: |
|
181 sys.stderr.write(" parsing build log %s\n" % os.path.split(self.logfilename)[1]) |
|
182 for l in f: |
|
183 # match in order of likelihood (most probable first) |
|
184 |
|
185 m = status_re.match(l) |
|
186 if m: |
|
187 self.recipes['TOTAL'] += 1 |
|
188 status = m.group(1) |
|
189 try: |
|
190 self.recipes[status] += 1 |
|
191 except KeyError: |
|
192 sys.stderr.write("unknown recipe status '%s'" % status) |
|
193 continue |
|
194 |
|
195 m = emake_invocation_re.match(l) |
|
196 if m: |
|
197 (adir, aname) = os.path.split(m.group(1)) |
|
198 if aname.find("pp")==-1: # no parallel parsing ones preferably |
|
199 sys.stderr.write(" found annotation file %s\n" % aname) |
|
200 |
|
201 # if --emake-maxagents is present then use that, otherwise use |
|
202 # the value passed in through the options. |
|
203 m = emake_maxagents_re.match(l) |
|
204 if m: |
|
205 maxagents = int(m.group(1)) |
|
206 else: |
|
207 maxagents = options.maxagents |
|
208 sys.stderr.write(" using maxagents %d as there is no record in the logs\n" % maxagents) |
|
209 |
|
210 self.annofile_refs.append( (os.path.join(logpath, "makefile", aname), maxagents) ) |
|
211 continue |
|
212 |
|
213 m = run_time_re.match(l) |
|
214 if m: |
|
215 self.build_duration = int(m.group(1)) |
|
216 continue |
|
217 |
|
218 m = sbs_version_re.match(l) |
|
219 if m: |
|
220 self.version = m.group(1) |
|
221 |
|
222 self.annofiles = [] |
|
223 for p in self.annofile_refs: |
|
224 self.annofiles.append(RaptorAnnofile(p[0], buildid, p[1])) |
|
225 |
|
226 def __str__(self): |
|
227 recipes = [" <metric name='raptor_%s_recipes' value='%d'/>\n" % x for x in self.recipes.items()] |
|
228 |
|
229 return "<raptorbuild logfile='%s'>\n" % os.path.split(self.logfilename)[-1] + \ |
|
230 " <metric name='raptor_version' value='%s' />\n" % (self.version) + \ |
|
231 " <metric name='raptor_duration_%s' value='%d' />\n" % (self.build, self.build_duration) + \ |
|
232 "".join(recipes) + \ |
|
233 "".join([str(a) for a in self.annofiles]) + \ |
|
234 "</raptorbuild>\n" |
|
235 |
|
236 |
|
237 |
|
238 class HeliumBuild(object): |
|
239 """A build with any version of Helium""" |
|
240 def __init__(self, logpath, buildid, options=None): |
|
241 self.options = options |
|
242 self.buildid = buildid |
|
243 self.logpath = logpath |
|
244 self.logfiles=[] |
|
245 |
|
246 def __str__(self): |
|
247 return self.buildid + \ |
|
248 "\n"+[str(a) for a in self.annofiles] + "\n" |
|
249 |
|
250 class Helium9Build(HeliumBuild): |
|
251 """ Filenames, structure etc conform to Helium 9 """ |
|
252 def __init__(self, logpath, buildid, options=None): |
|
253 super(Helium9Build,self).__init__(logpath, buildid, options) |
|
254 self.mainantlog = MainAntLog(logpath, buildid, options) |
|
255 self.raptorbuilds = [] |
|
256 |
|
257 # mcl_7901_201024_20100623181534_dfs_build_ncp_variants.build_input_compile.log |
|
258 # mcl_7901_201024_20100623181534_dfs_build_sf_variants.build_input_compile.log |
|
259 # mcl_7901_201024_20100623181534_dfs_build_winscw_dfs_build_winscw_input_compile.log |
|
260 # |
|
261 # ....but the problem is that the anno files have a slightly differing convention: |
|
262 # 92_7952_201022_003_dfs_build_ncp_dfs_variants.resource_deps.emake.anno |
|
263 # _dfs_build_ncp_variants |
|
264 # _dfs_build_ncp_dfs_variants |
|
265 # read the annofile names from inside the raptor log output |
|
266 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"]: |
|
267 try: |
|
268 self.raptorbuilds.append(RaptorBuild(logpath, buildid, r, options)) |
|
269 except LogfileNotFound, ex: |
|
270 sys.stderr.write(str(ex)) |
|
271 |
|
272 def __str__(self): |
|
273 |
|
274 raptor_duration = reduce(lambda x, y: x + y,[y.build_duration for y in self.raptorbuilds],0) |
|
275 return "<heliumbuild ver='9' id='%s'>\n" % (self.buildid) + \ |
|
276 "<metric name='total_duration' value='%d' />\n" % (self.mainantlog.build_duration) + \ |
|
277 "<metric name='raptor_duration' value='%d' />\n" % (raptor_duration) + \ |
|
278 "".join([str(a) for a in self.raptorbuilds ]) + \ |
|
279 "</heliumbuild>\n" |
|
280 |
|
281 |
|
282 class HeliumLogDir(object): |
|
283 """Multiple builds can be done one after another (usually when rebuilding |
|
284 things that failed, apparently) and their logs left in the output dir. |
|
285 The naming convention ensures that they don't overwrite each other. |
|
286 This class identifies each build and tries to analyse them one by one.""" |
|
287 def __init__(self, epocroot, options=None): |
|
288 self.logpath = os.path.join(epocroot, "output/logs") |
|
289 logs = MainAntLog.findall(self.logpath) |
|
290 self.builds = [] |
|
291 |
|
292 for b in logs.keys(): |
|
293 try: |
|
294 sys.stderr.write(" Found build with id %s\n" % b) |
|
295 build = Helium9Build(self.logpath, b, options) |
|
296 self.builds.append(build) |
|
297 except IOError,e: |
|
298 sys.stderr.write(" Buildid %s found but does not refer to a complete build\n" % b) |
|
299 sys.stderr.write(str(e)+"\n") |
|
300 |
|
301 def write(self, stream): |
|
302 for b in self.builds: |
|
303 stream.write(str(b)+"\n") |
|
304 |
|
305 |
|
306 parser = OptionParser(prog = "grokbuild", |
|
307 usage = """%prog [-h | options] path_to_EPOCROOT |
|
308 |
|
309 The build logs are usually in $EPOCROOT/output/logs""") |
|
310 |
|
311 parser.add_option("--maxagents", type="int", dest="maxagents", default=30, |
|
312 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." |
|
313 ) |
|
314 (options, args) = parser.parse_args() |
|
315 |
|
316 if len(args) == 0: |
|
317 sys.stderr.write("Need at least one argument: a path to the logs.\n") |
|
318 sys.exit(-1) |
|
319 |
|
320 epocroot = args[0] |
|
321 sys.stderr.write("Gathering Performance Metrics for %s\n" % epocroot) |
|
322 |
|
323 b = HeliumLogDir(epocroot, options) |
|
324 b.write(sys.stdout) |