A wrapper around a log message to log the user time of a deferred.

logDeferredTime.py

def logDeferredTime(deferred, logfn, message, extra=None):
    """Returns a deferred that wraps the passed in deferred and logs how long
    it took for the provided deferred to return (either callback or errback)
    from the time of the calling of this function. This creates a proxy
    Deferred that is passed all of the arguments that are passed to the
    provided deferred.

    deferred: The deferred that we wish to time.
    logfn: A function that is called with (message, extra=extra). IE.
           `logger.info`
    message: A log message to go along with the timing information.
    extra: A dictionary of keys/values to log.
    """
    startTime = default_timer()  # seconds since epoch
    extra = {} if extra is None else extra.copy()
    newDeferred = Deferred()

    def logTime():
        finishTime = default_timer()
        extra["executionSeconds"] = (finishTime-startTime)
        logfn(message, extra=extra)

    def deferredFinished(*args, **kwargs):
        logTime()
        newDeferred.callback(*args, **kwargs)

    def deferredFinishedError(failure, *args, **kwargs):
        logTime()
        newDeferred.errback(failure, *args, **kwargs)

    deferred.addCallbacks(deferredFinished, deferredFinishedError)

    return newDeferred