pythonのcProfileを使ってみる。 - malibu-bulldogの日記

python専用のプロファイラー，cProfileを使ってみました。

プロファイラーって？

実行されているプログラムの処理のいろんなものを測定してくれる開発ツールの事をさします。
多くの開発者はプロファイラーを使って関数単位で処理時間を測定してプログラムのボトルネックを探します。

C言語でLinux環境な人なんかはプロファイラーとしてvalgrindにcallgrindをのっけて測定とかよくやってますね。

とはいえ開発しているターゲットや開発環境によってはプロファイラーが無い，あっても使えない場合もありますが…

cProfileとは？

python用のプロファイラーです。
MacOSX等はXCodeを入れればこれらもインストールされるでしょう（多分，気づいたら入ってました！）。

Ubuntu10.04だと素の状態では入っていないので

sudo apt-get install python-profiler

しましょう。

cProfileを使ってみる

使い方は至って簡単で例えばmain.pyファイル中のメイン関数から始まる一連の処理を測定したければコンソール上で

python -m cProfile main.py

とします。適当に次のようなプログラムを用意しました。三つの関数と一つのメイン関数からなります。

def function1(n):
    counter = 0
    for i in range(n):
        counter += 1
    return counter

def function2(n):
    counter = 0
    for i in range(n):
        for j in range(n):
            counter += 1
    return counter

def function3(n):
    counter = 0
    for i in range(n):
        for j in range(n):
            for k in range(n):
                counter += 1
    return counter

def main():
    function1(500)
    function2(500)
    function^G3(500)
    return

if __name__ == "__main__":
    main()

function1は計算量のオーダーがfor文が一つなので $O(n)$ , function2は二重になっているので $O(n^2)$ , function3は $O(n^3)$ です。

cProfileを使った結果はこんな感じに

         251011 function calls in 14.775 CPU seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000   14.775   14.775 <string>:1(<module>)
        1    0.000    0.000   14.775   14.775 main.py:1(<module>)
        1    0.000    0.000    0.000    0.000 main.py:1(function1)
        1   12.991   12.991   14.746   14.746 main.py:14(function3)
        1    0.000    0.000   14.775   14.775 main.py:22(main)
        1    0.025    0.025    0.029    0.029 main.py:7(function2)
        1    0.000    0.000   14.775   14.775 {execfile}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
   251003    1.759    0.000    1.759    0.000 {range}

ログの各行は呼び出された関数の情報です。各列の項目は

ncallは関数呼び出し回数を表わしてます
tottimeは関数にかかった時間（複数回よばれたらトータル）
precallはtottime÷ncall
cumtime関数内で他の関数を呼び出しているならそれを含んだ時間
二番目のprecallはcumtime÷ncall
ファイル名，行番号，関数名

main.pyはログから $O(n^3)$ のfunction3が圧倒的に時間がかかっているのがわかりますね！

追記

ログをソートしたい場合，例えば次のような感じにします

 python -m cProfile -s time **.py 測定するプログラムへの引数

　-sオプションの後にキーワードです。timeを指定すれば速度の遅い順に並び替えられて出力されますよ〜