跟踪python中运行缓慢的原因

Question

在一个大型项目中，我遇到了一个非常慢的功能（说到几秒到几分钟的执行时间）。该函数可以完成很多事情，并且具有非常深的堆栈跟踪。尽管此函数的执行只涉及几个类，但是长运行时间的来源并不太明显。

我开始调试该功能，跟踪调用等，并发现跟踪包非常有用。有了这个，我可以确定一些函数，这些函数会一遍又一遍地汇编列表，实际上，在第一次执行后保存列表时，实际上导致了大约3倍的加速。

但是现在我真的看不到任何更明显的部分，因为跟踪包产生了几兆字节的文本，因此可以优化功能的地方，而且我看不到任何对我来说可疑的东西。

我考虑过使用跟踪的计时选项，以便为我提供一些有关运行时的概述，以查看哪些功能可能很慢-但是数据量太大，因此总的执行时间为列出了每个调用，但是跟踪软件包似乎不支持此调用吗？

另一个问题是，我想在哪个级别获得执行时间。相反，不是单个语句很慢，而是经常调用整个函数或不保存数据的情况。因此，我最终需要的是每个语句的平均执行时间乘以计数。后者可以由跟踪包生成。

除了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}