python twisted : retrieve a deferred's execution time

Question

I would like to know how long a Deferred takes to execute, from the time the first callback is fired to the final result.

Any ideas on how to do that, possibly in a non-invasive manner ( meaning no modification on any of the callback functions in order to track the execution time ) ?

Answer 1

If you are running your program with help of "twistd", then it has an option "--profile" which can help you with profiling twisted code.

twistd "other options" --profile=statsfile --profiler=cProfile --savestats

And to view the stats:

import pstats
stats = pstats.Stats('statsfile')
stats.sort_stats('time').print_stats()

Callbacks are executed immediately after the deferreds are fired. But immediately means that each callback in the deferred chain has to be executed and they would have their own execution time. Also various pieces of code will have their own slice of time for execution including the reactor loop.

So to say the word - immediately is to say as soon as possible.

Consider the following bad example :

from twisted.internet import reactor, defer
import time

def timeit(func):
    def wrapper(*arg):
        t1 = time.time()
        res = func(*arg)
        t2 = time.time()
        print '%s took %0.3f ms' % (func.func_name, (t2-t1)*1000.0)
        return res
    return wrapper

d = defer.Deferred()

@timeit
def callfunc1(result):
    print 'XXXXX'

@timeit   
def callfunc2(result):
    print 'YYYYY'

d.addCallback(callfunc1)   
d.addCallback(callfunc2)  
t1 = time.time()
d.callback(True)
t2 = time.time()
print '%0.3f ms' % ((t2-t1)*1000.0)

Output:

XXXXX
callfunc1 took 0.039 ms
YYYYY
callfunc2 took 0.005 ms
0.108 ms

Now if we tweak the above code to include a reactor and callLater

Answer 2

Profiling is a bit overkill for what I'd like to achieve.

I ended up with a solution that didn't imply heavy modifications on existing code, but is in no way "universal" :

my original code was something like :

def myfunc(*args):
    d = Deferred()
    d.addCallback(cb1)
    ...
    d.addCallback(lambda x: MyObject(x))

I now have:

def myfunc(*args):
    init_time = time.time()
    d = Deferred()
    d.addCallback(cb1)
    ...
    d.addCallback(lambda x: MyObject(x, init_time))

class MyObject:
    def __init__(self, *args):
        ...
        self.exec_time = time.time() - init_time

It does just what I want, but I was hoping the Deferred structure would expose something keeping track of the execution time itself, instead of having to tinker with my objects. From the source code, I can see no such thing is available : http://twistedmatrix.com/trac/browser/tags/releases/twisted-10.0.0/twisted/internet/defer.py#L137