python twisted : retrieve a deferred's execution time

I would like to know how long a Deferred takes to execute, from the time the first callback is 开发者_StackOverflowfired 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 ) ?

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

Guess you should profile your app, follow this way:

install this tool http://kcachegrind.sourceforge.net/html/Home.html

fire your twisted app and collect raw data:

twistd --savestats -n --profile=myapp.hotshot myapp

than, you convert 'hotshot' to 'calltree', run:

hotshot2cg myapp.hotshot > myapp.calltree

now we can view calltree in Kcachegrind tool.

kcachegrind myapp.calltree

with this tool you can view the call-graph of twisted event loop, execution time you can see in percents. so no need to patching the code, just run this tool and see

P.S. for checking the memory: How to use guppy/heapy for tracking down memory usage

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