timingwrapper.py

import time
import logging

log = logging.getLogger(__name__)


class Stopwatch(object):

    def __init__(self, wallclock=True):
        self.timefunc = time.time if wallclock else time.clock
        self.reset()

    def reset(self):
        self.started = self.timefunc()

    def elapsed(self):
        return self.timefunc() - self.started

    def read(self, precision=2):
        format = "%%.%if seconds" % precision
        return format % (self.timefunc() - self.started,)


class TimingWrapper(object):
    """Class attribute wrapper used to debug how long it takes to get and/or
    call attributes of the class.

    USAGE: add the following method to a class:

    def __getattribute__(self, name):
        try:
            return TimingWrapper.getattribute(self, name, threshold=<seconds>)
        except TimingWrapper.Fail:
            return super(<Class>, self).__getattribute__(name)
    """

    class Fail(Exception): pass

    def __init__(self, instance, attr, getTime=None, threshold=None, precision=4):
        self.instance = instance
        self.attr = attr
        self.threshold = threshold
        self.logValues = dict(
            instance=instance.__class__.__name__, # str(instance) is too busy
            attr=attr,
        )
        self.format = "%%(event)s [%%(elapsed).%if] %%(instance)s.%%(attr)s" % precision
        if getTime is not None:
            self.log(getTime, "get")

    @staticmethod
    def getattribute(instance, name, threshold=None):
        if name == "__class__":
            raise TimingWrapper.Fail(name) # avoid infinite recursion
        stopwatch = Stopwatch()
        value = super(instance.__class__, instance).__getattribute__(name)
        elapsed = stopwatch.elapsed()
        del stopwatch
        wrapper = TimingWrapper(instance, name, elapsed, threshold=threshold)
        return wrapper.wrap(value)

    def log(self, elapsed, event):
        if self.threshold is None or elapsed >= self.threshold:
            values = dict(self.logValues) # make a copy
            values.update(dict(elapsed=elapsed, event=event.upper().rjust(4)))
            log.debug(self.format, values)

    def wrap(self, obj):
        if callable(obj):
            self.method = obj
            return self
        else:
            return obj

    def __call__(self, *args, **kw):
        stopwatch = Stopwatch()
        try:
            return self.method(*args, **kw)
        finally:
            self.log(stopwatch.elapsed(), "call")