buildbot 0.8.6p1-1 / usr / share / pyshared / buildbot / status / progress.py

# This file is part of Buildbot.  Buildbot is free software: you can
# redistribute it and/or modify it under the terms of the GNU General Public
# License as published by the Free Software Foundation, version 2.
#
# This program is distributed in the hope that it will be useful, but WITHOUT
# ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS
# FOR A PARTICULAR PURPOSE.  See the GNU General Public License for more
# details.
#
# You should have received a copy of the GNU General Public License along with
# this program; if not, write to the Free Software Foundation, Inc., 51
# Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
#
# Copyright Buildbot Team Members


from twisted.internet import reactor
from twisted.spread import pb
from twisted.python import log
from buildbot import util
from buildbot.util.bbcollections import defaultdict

class StepProgress:
    """I keep track of how much progress a single BuildStep has made.

    Progress is measured along various axes. Time consumed is one that is
    available for all steps. Amount of command output is another, and may be
    better quantified by scanning the output for markers to derive number of
    files compiled, directories walked, tests run, etc.

    I am created when the build begins, and given to a BuildProgress object
    so it can track the overall progress of the whole build.

    """

    startTime = None
    stopTime = None
    expectedTime = None
    buildProgress = None
    debug = False

    def __init__(self, name, metricNames):
        self.name = name
        self.progress = {}
        self.expectations = {}
        for m in metricNames:
            self.progress[m] = None
            self.expectations[m] = None

    def setBuildProgress(self, bp):
        self.buildProgress = bp

    def setExpectations(self, metrics):
        """The step can call this to explicitly set a target value for one
        of its metrics. E.g., ShellCommands knows how many commands it will
        execute, so it could set the 'commands' expectation."""
        for metric, value in metrics.items():
            self.expectations[metric] = value
        self.buildProgress.newExpectations()

    def setExpectedTime(self, seconds):
        self.expectedTime = seconds
        self.buildProgress.newExpectations()

    def start(self):
        if self.debug: print "StepProgress.start[%s]" % self.name
        self.startTime = util.now()

    def setProgress(self, metric, value):
        """The step calls this as progress is made along various axes."""
        if self.debug:
            print "setProgress[%s][%s] = %s" % (self.name, metric, value)
        self.progress[metric] = value
        if self.debug:
            r = self.remaining()
            print " step remaining:", r
        self.buildProgress.newProgress()

    def finish(self):
        """This stops the 'time' metric and marks the step as finished
        overall. It should be called after the last .setProgress has been
        done for each axis."""
        if self.debug: print "StepProgress.finish[%s]" % self.name
        self.stopTime = util.now()
        self.buildProgress.stepFinished(self.name)

    def totalTime(self):
        if self.startTime != None and self.stopTime != None:
            return self.stopTime - self.startTime

    def remaining(self):
        if self.startTime == None:
            return self.expectedTime
        if self.stopTime != None:
            return 0 # already finished
        # TODO: replace this with cleverness that graphs each metric vs.
        # time, then finds the inverse function. Will probably need to save
        # a timestamp with each setProgress update, when finished, go back
        # and find the 2% transition points, then save those 50 values in a
        # list. On the next build, do linear interpolation between the two
        # closest samples to come up with a percentage represented by that
        # metric.

        # TODO: If no other metrics are available, just go with elapsed
        # time. Given the non-time-uniformity of text output from most
        # steps, this would probably be better than the text-percentage
        # scheme currently implemented.

        percentages = []
        for metric, value in self.progress.items():
            expectation = self.expectations[metric]
            if value != None and expectation != None:
                p = 1.0 * value / expectation
                percentages.append(p)
        if percentages:
            avg = reduce(lambda x,y: x+y, percentages) / len(percentages)
            if avg > 1.0:
                # overdue
                avg = 1.0
            if avg < 0.0:
                avg = 0.0
        if percentages and self.expectedTime != None:
            return self.expectedTime - (avg * self.expectedTime)
        if self.expectedTime is not None:
            # fall back to pure time
            return self.expectedTime - (util.now() - self.startTime)
        return None # no idea


class WatcherState:
    def __init__(self, interval):
        self.interval = interval
        self.timer = None
        self.needUpdate = 0

class BuildProgress(pb.Referenceable):
    """I keep track of overall build progress. I hold a list of StepProgress
    objects.
    """

    def __init__(self, stepProgresses):
        self.steps = {}
        for s in stepProgresses:
            self.steps[s.name] = s
            s.setBuildProgress(self)
        self.finishedSteps = []
        self.watchers = {}
        self.debug = 0

    def setExpectationsFrom(self, exp):
        """Set our expectations from the builder's Expectations object."""
        for name, metrics in exp.steps.items():
            s = self.steps[name]
            s.setExpectedTime(exp.times[name])
            s.setExpectations(exp.steps[name])

    def newExpectations(self):
        """Call this when one of the steps has changed its expectations.
        This should trigger us to update our ETA value and notify any
        subscribers."""
        pass # subscribers are not implemented: they just poll

    def stepFinished(self, stepname):
        assert(stepname not in self.finishedSteps)
        self.finishedSteps.append(stepname)
        if len(self.finishedSteps) == len(self.steps.keys()):
            self.sendLastUpdates()
            
    def newProgress(self):
        r = self.remaining()
        if self.debug:
            print " remaining:", r
        if r != None:
            self.sendAllUpdates()
        
    def remaining(self):
        # sum eta of all steps
        sum = 0
        for name, step in self.steps.items():
            rem = step.remaining()
            if rem == None:
                return None # not sure
            sum += rem
        return sum
    def eta(self):
        left = self.remaining()
        if left == None:
            return None # not sure
        done = util.now() + left
        return done


    def remote_subscribe(self, remote, interval=5):
        # [interval, timer, needUpdate]
        # don't send an update more than once per interval
        self.watchers[remote] = WatcherState(interval)
        remote.notifyOnDisconnect(self.removeWatcher)
        self.updateWatcher(remote)
        self.startTimer(remote)
        log.msg("BuildProgress.remote_subscribe(%s)" % remote)
    def remote_unsubscribe(self, remote):
        # TODO: this doesn't work. I think 'remote' will always be different
        # than the object that appeared in _subscribe.
        log.msg("BuildProgress.remote_unsubscribe(%s)" % remote)
        self.removeWatcher(remote)
        #remote.dontNotifyOnDisconnect(self.removeWatcher)
    def removeWatcher(self, remote):
        #log.msg("removeWatcher(%s)" % remote)
        try:
            timer = self.watchers[remote].timer
            if timer:
                timer.cancel()
            del self.watchers[remote]
        except KeyError:
            log.msg("Weird, removeWatcher on non-existent subscriber:",
                    remote)
    def sendAllUpdates(self):
        for r in self.watchers.keys():
            self.updateWatcher(r)
    def updateWatcher(self, remote):
        # an update wants to go to this watcher. Send it if we can, otherwise
        # queue it for later
        w = self.watchers[remote]
        if not w.timer:
            # no timer, so send update now and start the timer
            self.sendUpdate(remote)
            self.startTimer(remote)
        else:
            # timer is running, just mark as needing an update
            w.needUpdate = 1
    def startTimer(self, remote):
        w = self.watchers[remote]
        timer = reactor.callLater(w.interval, self.watcherTimeout, remote)
        w.timer = timer
    def sendUpdate(self, remote, last=0):
        self.watchers[remote].needUpdate = 0
        #text = self.asText() # TODO: not text, duh
        try:
            remote.callRemote("progress", self.remaining())
            if last:
                remote.callRemote("finished", self)
        except:
            log.deferr()
            self.removeWatcher(remote)

    def watcherTimeout(self, remote):
        w = self.watchers.get(remote, None)
        if not w:
            return # went away
        w.timer = None
        if w.needUpdate:
            self.sendUpdate(remote)
            self.startTimer(remote)
    def sendLastUpdates(self):
        for remote in self.watchers.keys():
            self.sendUpdate(remote, 1)
            self.removeWatcher(remote)

        
class Expectations:
    debug = False
    # decay=1.0 ignores all but the last build
    # 0.9 is short time constant. 0.1 is very long time constant
    # TODO: let decay be specified per-metric
    decay = 0.5

    def __init__(self, buildprogress):
        """Create us from a successful build. We will expect each step to
        take as long as it did in that build."""

        # .steps maps stepname to dict2
        # dict2 maps metricname to final end-of-step value
        self.steps = defaultdict(dict)

        # .times maps stepname to per-step elapsed time
        self.times = {}

        for name, step in buildprogress.steps.items():
            self.steps[name] = {}
            for metric, value in step.progress.items():
                self.steps[name][metric] = value
            self.times[name] = None
            if step.startTime is not None and step.stopTime is not None:
                self.times[name] = step.stopTime - step.startTime

    def wavg(self, old, current):
        if old is None:
            return current
        if current is None:
            return old
        else:
            return (current * self.decay) + (old * (1 - self.decay))

    def update(self, buildprogress):
        for name, stepprogress in buildprogress.steps.items():
            old = self.times.get(name)
            current = stepprogress.totalTime()
            if current == None:
                log.msg("Expectations.update: current[%s] was None!" % name)
                continue
            new = self.wavg(old, current)
            self.times[name] = new
            if self.debug:
                print "new expected time[%s] = %s, old %s, cur %s" % \
                      (name, new, old, current)
            
            for metric, current in stepprogress.progress.items():
                old = self.steps[name].get(metric)
                new = self.wavg(old, current)
                if self.debug:
                    print "new expectation[%s][%s] = %s, old %s, cur %s" % \
                          (name, metric, new, old, current)
                self.steps[name][metric] = new

    def expectedBuildTime(self):
        if None in self.times.values():
            return None
        #return sum(self.times.values())
        # python-2.2 doesn't have 'sum'. TODO: drop python-2.2 support
        s = 0
        for v in self.times.values():
            s += v
        return s