在python中跟蹤慢速運行函數的原因

Question

在一個大型項目中，我遇到了一個非常慢的函數（說到秒到分鐘執行時間）。該函數做了很多事情，並有一個非常深的stacktrace。雖然這個函數的執行只涉及幾個類，但長運行時間的來源並不明顯。

我開始調試函數，跟蹤調用等，發現trace包相當有用。有了這個功能，我可以識別一些能夠反覆地組合列表的函數，在第一次執行後保存列表時，實際上會導致大約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}