唯物是真 @Scaled_Wurm

プログラミング(主にPython2.7)とか機械学習とか

cProfileでpythonスクリプトのボトルネックを調べる

Pythonのスクリプトの遅い部分を調べるためにcProfileという標準のプロファイラを使ってみました.

プロファイラというのはプログラムの実行効率を調べるツールです.
cProfileを使うと関数が呼び出された回数(再帰の有無含む)や,どれぐらいの時間を処理に使ったかなどがわかります.

やり方

スクリプトの時間をはかる方法とPython内で関数を指定して調べる方法の2つがありますが,前者だけ紹介します.
以下のようにすれば指定したスクリプトの計測を行うことができます.

python -m cProfile -s time スクリプト名.py

標準のライブラリですが,OSによっては別にインストールしなければならない場合があるそうです.

実験用のプログラム

以下のプログラムを使って実験します.
フィボナッチ数列のn番目の項を求めるプログラムで,fib_recursiveが再帰,fib_memoが再帰+メモ化,fib_loopがループによる解法となっています.

def fib_recursive(n):
    if n == 1:
        return 1
    if n == 2:
        return 1
    return fib_recursive(n - 1) + fib_recursive(n - 2)

memo = {}
def fib_memo(n):
    if n == 1:
        return 1
    if n == 2:
        return 1
    if n in memo:
        return memo[n]
    else:
        memo[n] = fib_memo(n - 1) + fib_memo(n - 2)
        return memo[n]


def fib_loop(n):
    a = 1
    b = 1
    for i in xrange(n - 2):
        a, b = a + b, a
    return a

if __name__ == "__main__":
    fib_recursive(40)
    fib_memo(40)
    fib_loop(40)

結果

         204668389 function calls (5 primitive calls) in 62.531 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
204668309/1   62.530    0.000   62.530   62.530 prof.py:1(fib_recursive)
        1    0.001    0.001   62.531   62.531 prof.py:1(<module>)
     77/1    0.000    0.000    0.000    0.000 prof.py:9(fib_memo)
        1    0.000    0.000    0.000    0.000 prof.py:21(fib_loop)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
読み方

最初の行を見ると,204668389回の関数の呼び出し(再帰含む)があり,5回の再帰を含まない呼び出しがあったことがわかります.
また62.531秒の時間がかかっています.


表の各列はそれぞれ以下のようなことを表しています.

  1. ncalls: 関数の呼び出し回数(再帰含む/含まない)
  2. tottime: 関数内での所要時間
  3. percall: 1回の関数呼び出しあたりのtottime
  4. cumtime: 内部で読んだ別の関数を含む所要時間
  5. percall: 1回の関数呼び出しあたりのcumtime
考察

tottimeを見るとfib_recursiveが最も時間がかかっていることがわかります.


関数の呼び出し回数(ncalls)を見ると二億回以上もfib_recursiveは関数呼び出しを行なっているのに対してメモ化を行ったfib_memoはおよそ80回弱の関数呼び出ししか行なっておらず,関数の呼び出し回数を大幅に削減できていることがプロファイラの結果を見るとわかります.

ソート

"-s time"は「関数内の処理時間でソートする」というのを意味していて"time"以外にも以下のようなものを指定できます.

正式名 内容
'calls' 呼び出し回数
'cumulative' 累積時間
'file' ファイル名
'module' モジュール名
'pcalls' プリミティブな呼び出し回数
'line' 行番号
'name' 関数名
'nfl' 関数名/ファイル名/行番号
'stdname' 標準名
'time' 内部時間