日記

日々のことと、Python/Django/PHP/Laravel/nodejs などソフトウェア開発のことを書き綴ります

Pythonのプログラムをプロファイリングする

TwitterFacebookばかりで、めっきりと更新が止まってました。
久々に更新ということで、今回は仕事でバッチ処理を書いたときに処理時間を調べるために使った Pythonの cProfileの使い方を書き残しておきたいと思います。

Pythonのプロファイラー

Pythonは、ビルトインのプロファイラを備えており、profile, cProfile, hostshotがあります。今回は、cProfileを使います。cProfileは、profileのC言語実装版です。逆にprofileはピュアPython実装ですね。

cProfileを使うと、実行したプログラムの関数の呼び出し回数、関数毎の実行時間などを取得できます。では実際に試してみます。

計測するプログラム

プロファイラを実行するには計測する処理が必要なので、何か適当なコードを書きます。

ファイルは「foobar.py」として保存します。

def foo():
   print 'foo'

def bar():
   print 'bar'

def foobar100():
    for num in range(100):
        foo()
        bar()

def foobar1000():
    for num in range(1000):
        foo()
        bar()

def main():
   foobar100()
   foobar1000()

if __name__ == '__main__':
    main()

プロファイルしてみる

前述のコードをプロファイラにかけて、解析します。
プロファイラはコマンドラインから以下のように実行します。

python -m cProfile foobar.py

実行結果は以下のようになります。

(省略)
foo
bar
         2209 function calls in 0.640 CPU seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.640    0.640 <string>:1(<module>)
        1    0.000    0.000    0.640    0.640 foobar.py:1(<module>)
     1100    0.294    0.000    0.294    0.000 foobar.py:1(foo)
        1    0.003    0.003    0.371    0.371 foobar.py:12(foobar1000)
        1    0.000    0.000    0.640    0.640 foobar.py:17(main)
     1100    0.341    0.000    0.341    0.000 foobar.py:4(bar)
        1    0.001    0.001    0.269    0.269 foobar.py:7(foobar100)
        1    0.000    0.000    0.640    0.640 {execfile}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        2    0.000    0.000    0.000    0.000 {range}

出力された情報の見方は

ncalls 関数の呼び出し回数
tottime 関数の合計処理時間
percall tottimeの呼び出し毎の平均処理時間
cumtime 関数内での処理時間(他の関数の処理時間を含む)
percall cutimeの呼び出し毎の平均処理時間

こんな感じです。
foo関数とbar関数は、foobar100とfoobar1000から呼び出され、合計の呼び出し回数が1100回なので、ncallsがそれぞれ1100となっていますね。

プロファイラを使うと、実行時間、実行回数などがはっきりと数値化されます。同じ処理を不用意に何度も呼び出すのは、格好悪いのですが、複雑な処理、長い処理などをコーディングしていると実装中は、なかなか自分では気が付きにくいもの。こういったツールを使うことで無駄に処理が行われていないかを確認することができます。特に時間が掛かるけど、なるべく処理速度を上げてレスポンススピードを速くしたいときは、参考指標としてプロファイラを利用すると非常に有効です。意外なところで時間が掛かっていることも分かったりして、プログラマのレベルが一個あがること間違いなしです。

もっと実案件用途な使い方

Pythonというと、バッチ処理よりもWebアプリに使うことが多いのではないかと思います。そんなときは、コマンドラインから実行しないし、どうやって処理を測ったら良いのかサッパリです。でも、cProfileもPythonのモジュールなので、APIとして利用できます。使い方はこんな感じ。

from foobar import main
import cProfile

p = cProfile.Profile()
p.runcall(main)
p.print_stats()

さっきと同じように結果は

>>> p.print_stats()
         2206 function calls in 0.417 CPU seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     1100    0.207    0.000    0.207    0.000 foobar.py:1(foo)
        1    0.003    0.003    0.368    0.368 foobar.py:12(foobar1000)
        1    0.000    0.000    0.417    0.417 foobar.py:17(main)
     1100    0.207    0.000    0.207    0.000 foobar.py:4(bar)
        1    0.000    0.000    0.049    0.049 foobar.py:7(foobar100)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        2    0.000    0.000    0.000    0.000 {range}

こんな感じです。これだったら、main関数のようなエントリーポイントを用意すれば、Webアプリケーションのフレームワークを使用していても、そのフレームワーク上で動いた時のプロファイルができます。Djangoの場合だと

python manage.py shell

コマンドラインを起動しておいて、cProfileを実行すればDjangoのライブラリに依存していても割とスムーズに起動できると思います。ま、HttpRequestとかに依存しているような views.pyの計測は大変だと思いますが、アプリケーションの基幹コードを views.py に書いてしまうのがナンセンスだと思うのでスルーです。

また、APIとして cProfileを使用する時は、項目を指定した並べ替えとかも楽ちんです。

from foobar import main
import cProfile
cProfile('main()', 'foobar')

import pstats
ps = pstats.Stats('foobar')
ps.sort_stats('time').print_stats()

これの実行結果は

>>> ps.sort_stats('time').print_stats()
Thu Jun 23 20:27:02 2011    foobar

         2207 function calls in 0.409 CPU seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     1100    0.203    0.000    0.203    0.000 foobar.py:1(foo)
     1100    0.203    0.000    0.203    0.000 foobar.py:4(bar)
        1    0.003    0.003    0.366    0.366 foobar.py:12(foobar1000)
        1    0.000    0.000    0.043    0.043 foobar.py:7(foobar100)
        2    0.000    0.000    0.000    0.000 {range}
        1    0.000    0.000    0.409    0.409 foobar.py:17(main)
        1    0.000    0.000    0.409    0.409 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}


<pstats.Stats instance at 0x02833210>

こんな感じになります。前の例とは違って、関数内の処理時間の降順でソートされています。すこし実行時のコードを説明すると

cProfile.run('main()', 'foobar')

cProfile.runの第一引数はPythonのコードを指定します。第二引数は、分かりにくいのですがファイル名です。カレントディレクトリに foobarファイルが生成されていると思います。このファイルに cProfileがプロファイリングしたデータ(バイナリデータ)が書き出されており、pstatsモジュールがこのファイルを読み込むことができます。そして pstatsモジュールで人間が読みやすい形にフォーマットしています。

まとめ

駆け足で説明してしまいましたが、Pythonのプロファイラはこんな感じの使い方で、必要最低限の機能は備えています。
実際のところ、フレームワークを使ったりすると call stackが酷くて、自分のコードとフレームワークのコードをより分けることも大変だったりするのですが、どこでどれだけ処理時間を取られレているか分かるだけでも大きな一歩。あとは簡単なスクリプトを書いたり、Excelを駆使するなどすれば、かなり役に立つ統計情報になります。

何か処理が遅いかも?と思った時は、見なかったことにしないで一度プロファイリングしてみることをオススメします。

今回は処理速度のみのプロファイリングでしたが、本当はメモリ使用量などもプロファイリングする必要はあります。それはまたの機会と言うことで。