| 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 |