Python Twisted：获取延迟执行的时间

Question

我想知道Deferred执行的时间长短，从第一个回调函数被触发到最终结果。有没有什么方法可以做到这一点，可能是以非侵入方式（即不修改任何回调函数以跟踪执行时间）？

- user304965

Answer 1

如果您正在使用“twistd”运行程序，则可以使用选项“--profile”来帮助您对扭曲代码进行分析。

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

要查看统计数据：

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

回调函数在延迟对象被触发后立即执行。但是“立即”指的是延迟链中的每个回调都必须被执行，并且它们会有自己的执行时间。此外，包括反应器循环在内的各种代码片段也将有它们自己的执行时间。

因此，“立即”一词意味着尽快执行。

考虑以下糟糕的示例：

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)

输出：

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

现在，如果我们修改上面的代码，加入反应器和callLater。

- pyfunc

Answer 2

如果您想优化应用性能，请按照以下步骤操作：

安装此工具

运行您的twisted应用并收集原始数据：

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

然后将'hotshot'转换为'calltree'：

hotshot2cg myapp.hotshot > myapp.calltree

现在可以使用Kcachegrind工具查看调用树。

kcachegrind myapp.calltree

使用此工具，您可以查看twisted事件循环的调用图和百分比执行时间。所以无需修改代码，只需运行此工具即可。

P.S. 检查内存使用情况:

如何使用guppy/heapy跟踪内存使用情况

- far

---

hotshot2cg命令提供了什么功能？我在pip或brew中找不到任何相关信息，也没有在网上找到任何提及它的内容。 - Vitali

hotshot2cg类似于转换器，是KCacheGrind应用程序的一部分，因此应首先安装它。 - far

我安装了kcache grind，但仍无法运行hotshot2cg。我找不到任何算法/软件将hotshot转换为calltree。Downvote。 - Wax Cage

@WaxCage 命令是 'hotshot2calltree'。不过，hotshot（格式）似乎已经过时了，被pstats取代，这就是cProfile现在提供的内容。你可以使用 pyprof2calltree 将其转换。 - hnhn

Answer 3

性能分析对于我想要实现的目标来说有点过头了。

最终我找到了一个解决方案，它不需要对现有代码进行大量修改，但并不是“通用”的：

我的原始代码大致如下：

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

我现在有：

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

它做了我想要的事情，但我希望 Deferred 结构会暴露一些跟踪执行时间本身的东西，而不是必须调整我的对象。从源代码中，我看不到有这样的东西可用：http://twistedmatrix.com/trac/browser/tags/releases/twisted-10.0.0/twisted/internet/defer.py#L137

- user304965

---

@user304965：我有些犹豫要给出这样的答案，主要是因为你需要为回调函数进行性能分析。如果你正在编写自己的代码，那么这是可能的。但是，为了达到这个目的而对代码进行插装是很丑陋的。如果你正在使用其他模块的回调函数，甚至连这个都做不到。想法是回调函数会立即触发，但这取决于许多周围的事情。 - pyfunc