OLD | NEW |
| (Empty) |
1 # -*- test-case-name: buildbot.test.test_status -*- | |
2 | |
3 from twisted.internet import reactor | |
4 from twisted.spread import pb | |
5 from twisted.python import log | |
6 from buildbot import util | |
7 | |
8 class StepProgress: | |
9 """I keep track of how much progress a single BuildStep has made. | |
10 | |
11 Progress is measured along various axes. Time consumed is one that is | |
12 available for all steps. Amount of command output is another, and may be | |
13 better quantified by scanning the output for markers to derive number of | |
14 files compiled, directories walked, tests run, etc. | |
15 | |
16 I am created when the build begins, and given to a BuildProgress object | |
17 so it can track the overall progress of the whole build. | |
18 | |
19 """ | |
20 | |
21 startTime = None | |
22 stopTime = None | |
23 expectedTime = None | |
24 buildProgress = None | |
25 debug = False | |
26 | |
27 def __init__(self, name, metricNames): | |
28 self.name = name | |
29 self.progress = {} | |
30 self.expectations = {} | |
31 for m in metricNames: | |
32 self.progress[m] = None | |
33 self.expectations[m] = None | |
34 | |
35 def setBuildProgress(self, bp): | |
36 self.buildProgress = bp | |
37 | |
38 def setExpectations(self, metrics): | |
39 """The step can call this to explicitly set a target value for one | |
40 of its metrics. E.g., ShellCommands knows how many commands it will | |
41 execute, so it could set the 'commands' expectation.""" | |
42 for metric, value in metrics.items(): | |
43 self.expectations[metric] = value | |
44 self.buildProgress.newExpectations() | |
45 | |
46 def setExpectedTime(self, seconds): | |
47 self.expectedTime = seconds | |
48 self.buildProgress.newExpectations() | |
49 | |
50 def start(self): | |
51 if self.debug: print "StepProgress.start[%s]" % self.name | |
52 self.startTime = util.now() | |
53 | |
54 def setProgress(self, metric, value): | |
55 """The step calls this as progress is made along various axes.""" | |
56 if self.debug: | |
57 print "setProgress[%s][%s] = %s" % (self.name, metric, value) | |
58 self.progress[metric] = value | |
59 if self.debug: | |
60 r = self.remaining() | |
61 print " step remaining:", r | |
62 self.buildProgress.newProgress() | |
63 | |
64 def finish(self): | |
65 """This stops the 'time' metric and marks the step as finished | |
66 overall. It should be called after the last .setProgress has been | |
67 done for each axis.""" | |
68 if self.debug: print "StepProgress.finish[%s]" % self.name | |
69 self.stopTime = util.now() | |
70 self.buildProgress.stepFinished(self.name) | |
71 | |
72 def totalTime(self): | |
73 if self.startTime != None and self.stopTime != None: | |
74 return self.stopTime - self.startTime | |
75 | |
76 def remaining(self): | |
77 if self.startTime == None: | |
78 return self.expectedTime | |
79 if self.stopTime != None: | |
80 return 0 # already finished | |
81 # TODO: replace this with cleverness that graphs each metric vs. | |
82 # time, then finds the inverse function. Will probably need to save | |
83 # a timestamp with each setProgress update, when finished, go back | |
84 # and find the 2% transition points, then save those 50 values in a | |
85 # list. On the next build, do linear interpolation between the two | |
86 # closest samples to come up with a percentage represented by that | |
87 # metric. | |
88 | |
89 # TODO: If no other metrics are available, just go with elapsed | |
90 # time. Given the non-time-uniformity of text output from most | |
91 # steps, this would probably be better than the text-percentage | |
92 # scheme currently implemented. | |
93 | |
94 percentages = [] | |
95 for metric, value in self.progress.items(): | |
96 expectation = self.expectations[metric] | |
97 if value != None and expectation != None: | |
98 p = 1.0 * value / expectation | |
99 percentages.append(p) | |
100 if percentages: | |
101 avg = reduce(lambda x,y: x+y, percentages) / len(percentages) | |
102 if avg > 1.0: | |
103 # overdue | |
104 avg = 1.0 | |
105 if avg < 0.0: | |
106 avg = 0.0 | |
107 if percentages and self.expectedTime != None: | |
108 return self.expectedTime - (avg * self.expectedTime) | |
109 if self.expectedTime is not None: | |
110 # fall back to pure time | |
111 return self.expectedTime - (util.now() - self.startTime) | |
112 return None # no idea | |
113 | |
114 | |
115 class WatcherState: | |
116 def __init__(self, interval): | |
117 self.interval = interval | |
118 self.timer = None | |
119 self.needUpdate = 0 | |
120 | |
121 class BuildProgress(pb.Referenceable): | |
122 """I keep track of overall build progress. I hold a list of StepProgress | |
123 objects. | |
124 """ | |
125 | |
126 def __init__(self, stepProgresses): | |
127 self.steps = {} | |
128 for s in stepProgresses: | |
129 self.steps[s.name] = s | |
130 s.setBuildProgress(self) | |
131 self.finishedSteps = [] | |
132 self.watchers = {} | |
133 self.debug = 0 | |
134 | |
135 def setExpectationsFrom(self, exp): | |
136 """Set our expectations from the builder's Expectations object.""" | |
137 for name, metrics in exp.steps.items(): | |
138 s = self.steps[name] | |
139 s.setExpectedTime(exp.times[name]) | |
140 s.setExpectations(exp.steps[name]) | |
141 | |
142 def newExpectations(self): | |
143 """Call this when one of the steps has changed its expectations. | |
144 This should trigger us to update our ETA value and notify any | |
145 subscribers.""" | |
146 pass # subscribers are not implemented: they just poll | |
147 | |
148 def stepFinished(self, stepname): | |
149 assert(stepname not in self.finishedSteps) | |
150 self.finishedSteps.append(stepname) | |
151 if len(self.finishedSteps) == len(self.steps.keys()): | |
152 self.sendLastUpdates() | |
153 | |
154 def newProgress(self): | |
155 r = self.remaining() | |
156 if self.debug: | |
157 print " remaining:", r | |
158 if r != None: | |
159 self.sendAllUpdates() | |
160 | |
161 def remaining(self): | |
162 # sum eta of all steps | |
163 sum = 0 | |
164 for name, step in self.steps.items(): | |
165 rem = step.remaining() | |
166 if rem == None: | |
167 return None # not sure | |
168 sum += rem | |
169 return sum | |
170 def eta(self): | |
171 left = self.remaining() | |
172 if left == None: | |
173 return None # not sure | |
174 done = util.now() + left | |
175 return done | |
176 | |
177 | |
178 def remote_subscribe(self, remote, interval=5): | |
179 # [interval, timer, needUpdate] | |
180 # don't send an update more than once per interval | |
181 self.watchers[remote] = WatcherState(interval) | |
182 remote.notifyOnDisconnect(self.removeWatcher) | |
183 self.updateWatcher(remote) | |
184 self.startTimer(remote) | |
185 log.msg("BuildProgress.remote_subscribe(%s)" % remote) | |
186 def remote_unsubscribe(self, remote): | |
187 # TODO: this doesn't work. I think 'remote' will always be different | |
188 # than the object that appeared in _subscribe. | |
189 log.msg("BuildProgress.remote_unsubscribe(%s)" % remote) | |
190 self.removeWatcher(remote) | |
191 #remote.dontNotifyOnDisconnect(self.removeWatcher) | |
192 def removeWatcher(self, remote): | |
193 #log.msg("removeWatcher(%s)" % remote) | |
194 try: | |
195 timer = self.watchers[remote].timer | |
196 if timer: | |
197 timer.cancel() | |
198 del self.watchers[remote] | |
199 except KeyError: | |
200 log.msg("Weird, removeWatcher on non-existent subscriber:", | |
201 remote) | |
202 def sendAllUpdates(self): | |
203 for r in self.watchers.keys(): | |
204 self.updateWatcher(r) | |
205 def updateWatcher(self, remote): | |
206 # an update wants to go to this watcher. Send it if we can, otherwise | |
207 # queue it for later | |
208 w = self.watchers[remote] | |
209 if not w.timer: | |
210 # no timer, so send update now and start the timer | |
211 self.sendUpdate(remote) | |
212 self.startTimer(remote) | |
213 else: | |
214 # timer is running, just mark as needing an update | |
215 w.needUpdate = 1 | |
216 def startTimer(self, remote): | |
217 w = self.watchers[remote] | |
218 timer = reactor.callLater(w.interval, self.watcherTimeout, remote) | |
219 w.timer = timer | |
220 def sendUpdate(self, remote, last=0): | |
221 self.watchers[remote].needUpdate = 0 | |
222 #text = self.asText() # TODO: not text, duh | |
223 try: | |
224 remote.callRemote("progress", self.remaining()) | |
225 if last: | |
226 remote.callRemote("finished", self) | |
227 except: | |
228 log.deferr() | |
229 self.removeWatcher(remote) | |
230 | |
231 def watcherTimeout(self, remote): | |
232 w = self.watchers.get(remote, None) | |
233 if not w: | |
234 return # went away | |
235 w.timer = None | |
236 if w.needUpdate: | |
237 self.sendUpdate(remote) | |
238 self.startTimer(remote) | |
239 def sendLastUpdates(self): | |
240 for remote in self.watchers.keys(): | |
241 self.sendUpdate(remote, 1) | |
242 self.removeWatcher(remote) | |
243 | |
244 | |
245 class Expectations: | |
246 debug = False | |
247 # decay=1.0 ignores all but the last build | |
248 # 0.9 is short time constant. 0.1 is very long time constant | |
249 # TODO: let decay be specified per-metric | |
250 decay = 0.5 | |
251 | |
252 def __init__(self, buildprogress): | |
253 """Create us from a successful build. We will expect each step to | |
254 take as long as it did in that build.""" | |
255 | |
256 # .steps maps stepname to dict2 | |
257 # dict2 maps metricname to final end-of-step value | |
258 self.steps = {} | |
259 | |
260 # .times maps stepname to per-step elapsed time | |
261 self.times = {} | |
262 | |
263 for name, step in buildprogress.steps.items(): | |
264 self.steps[name] = {} | |
265 for metric, value in step.progress.items(): | |
266 self.steps[name][metric] = value | |
267 self.times[name] = None | |
268 if step.startTime is not None and step.stopTime is not None: | |
269 self.times[name] = step.stopTime - step.startTime | |
270 | |
271 def wavg(self, old, current): | |
272 if old is None: | |
273 return current | |
274 if current is None: | |
275 return old | |
276 else: | |
277 return (current * self.decay) + (old * (1 - self.decay)) | |
278 | |
279 def update(self, buildprogress): | |
280 for name, stepprogress in buildprogress.steps.items(): | |
281 old = self.times[name] | |
282 current = stepprogress.totalTime() | |
283 if current == None: | |
284 log.msg("Expectations.update: current[%s] was None!" % name) | |
285 continue | |
286 new = self.wavg(old, current) | |
287 self.times[name] = new | |
288 if self.debug: | |
289 print "new expected time[%s] = %s, old %s, cur %s" % \ | |
290 (name, new, old, current) | |
291 | |
292 for metric, current in stepprogress.progress.items(): | |
293 old = self.steps[name][metric] | |
294 new = self.wavg(old, current) | |
295 if self.debug: | |
296 print "new expectation[%s][%s] = %s, old %s, cur %s" % \ | |
297 (name, metric, new, old, current) | |
298 self.steps[name][metric] = new | |
299 | |
300 def expectedBuildTime(self): | |
301 if None in self.times.values(): | |
302 return None | |
303 #return sum(self.times.values()) | |
304 # python-2.2 doesn't have 'sum'. TODO: drop python-2.2 support | |
305 s = 0 | |
306 for v in self.times.values(): | |
307 s += v | |
308 return s | |
OLD | NEW |