python - 追踪python中运行缓慢的函数的原因

Question

在一个大型项目中，我遇到了一个非常慢的函数(执行时间是几秒到几分钟)。该函数做了很多事情并且有非常深的堆栈跟踪。虽然只有少数几个类参与了此功能的执行，但运行时间长的原因并不太明显。

我开始调试函数、跟踪调用等，发现 trace包挺实用的。有了这个，我可以识别出一些会一遍又一遍地组装列表的函数，这实际上会在第一次执行后保存列表时带来大约 3 倍的加速。

但现在我真的看不到任何更明显的部分，因为跟踪包会生成几兆字节的文本，所以可以优化函数，而且我无法发现任何对我来说看起来可疑的东西。

我想过使用跟踪的计时选项，给我一些关于运行时的概述，看看哪些功能可能很慢 - 但数据量太大了，所以一个总结会很好列出了每个调用的执行时间，但是跟踪包似乎不支持？

还有一个问题是，我希望获得哪个级别的执行时间。不是单个语句慢，而是整个函数被频繁调用或数据未保存......所以我最终需要的是每条语句的平均执行时间乘以计数。后面的可以通过trace包生成。

除了 pdb 和 trace 之外，还有其他我可以使用的工具吗？

Answer 1

您是否尝试过分析代码？下面是一个使用 cProfile 收集有关不同函数执行时间的汇总统计信息的示例:

import cProfile, pstats, StringIO
import time

# simulate a delay
def delay(ms):
    startms = int(round(time.time() * 1000))
    while (int(round(time.time() * 1000)) - startms <= ms):
        pass

def foo1():
    delay(100)

def foo2():
    for x in range(10):
        foo1()

def foo3():
    for x in range(20):
        foo1()

def foo4():
    foo2()
    foo3()

if __name__ == '__main__':
    pr = cProfile.Profile()
    pr.enable()  # start profiling

    foo4()

    pr.disable()  # end profiling
    s = StringIO.StringIO()
    sortby = 'cumulative'
    ps = pstats.Stats(pr, stream=s).sort_stats(sortby)
    ps.print_stats()
    print s.getvalue()

这是输出:

         4680454 function calls in 3.029 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    3.029    3.029 C:\Temp\test.py:21(foo4)
       30    0.000    0.000    3.029    0.101 C:\Temp\test.py:10(foo1)
       30    2.458    0.082    3.029    0.101 C:\Temp\test.py:5(delay)
        1    0.000    0.000    2.020    2.020 C:\Temp\test.py:17(foo3)
        1    0.000    0.000    1.010    1.010 C:\Temp\test.py:13(foo2)
  2340194    0.308    0.000    0.308    0.000 {round}
  2340194    0.263    0.000    0.263    0.000 {time.time}
        2    0.000    0.000    0.000    0.000 {range}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}