Pythonで低速実行関数の原因を追跡します

Question

大きなプロジェクトでは、非常に遅い（数秒から数分の実行時間）という機能に遭遇しました。この関数は多くのことを行い、非常に深いスタックトレースを持っています。この関数の実行には少数のクラスしか関与していませんが、長いランタイムがどこから来るのかはそれほど明白ではありません。

私は関数のデバッグを開始し、コールなどをトレースして、traceパッケージがかなり役に立ちました。これにより、リストを繰り返しアセンブルするいくつかの関数を特定することができました。実際には、最初の実行後にリストを保存すると、実際には約3倍のスピードアップにつながります。

しかし、トレースパッケージで数メガバイトのテキストが生成され、私に疑わしいものが見つからないため、関数を最適化することはできません。

トレースのタイミングオプションを使用してランタイムの概要を知り、どの機能が遅いのかを確認することを考えましたが、データ量が大きすぎるため、各呼び出しの合計実行時間が表示されますが、これはトレースパッケージでサポートされていないようです。

さらに別の質問は、どのレベルで実行時間を取得したいかです。単一のステートメントが遅いのではなく、関数全体がかなり頻繁に呼び出されるか、データが保存されない場合はありません。 最終的にステートメントごとの平均実行時間にカウントを掛けたものが必要です。後者は、トレースパッケージによって生成することができます。

pdbとトレースの他に、他にもツールがありますか？

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}