Python: profile/cProfile モジュールでボトルネックを調べる

プログラムを作ってみたは良いけれど、想定していたよりもパフォーマンスが出ないという事態はよくある。そんなときはパフォーマンス・チューニングをするわけだけど、それにはまず測定が必要になる。具体的に何を測定するかというと、プログラムの中のどこがボトルネックになっているかという点だ。この測定の作業は一般にプロファイリングと呼ばれる。

プロファイリングにはふたつの種類がある。ひとつ目は今回紹介する profile/cProfile モジュールが採用している決定論的プロファイリング。そして、もうひとつが統計的プロファイリングだ。

決定論的プロファイリングでは、プログラムが実行されていく過程を逐一記録していく。そのため、時間のかかっている処理を正確に把握することができる。ただし、測定自体がプログラムに与える影響 (プローブ・エフェクト) も大きくなる。

それに対し統計的プロファイリングでは、プログラムが実行されていく過程をランダムに記録していく。これは、統計的にいえばプログラムが実行されていく過程の全体を母集団と捉えて、そこから標本を抽出している。そして、抽出した標本から母集団を推定する形で、呼び出しの多い処理や時間のかかっている処理を推定することになる。この場合、結果はあくまで推定 (一定の割合で誤りを許容すること) になるものの、測定自体が与える影響は比較的小さくなる。

profile/cProfile モジュール

前置きが長くなったけど、今回は Python の標準ライブラリに用意されているプロファイリング用のモジュールを紹介する。具体的には profile と cProfile というふたつの実装で、どちらも前述した通り決定論的プロファイリングを採用している。ふたつある理由は profile が Pure Python の実装で、cProfile が C 拡張モジュールを使った実装になっている。それぞれの特徴は、profile に比べると cProfile は測定にかかるオーバーヘッドが少ない代わりに、ユーザの拡張性が低くなっている。使い分けについては、一般的なユースケースでは cProfile を常に使っていれば良さそうだ。

今回使った環境は次の通り。

$ sw_vers 
ProductName:    Mac OS X
ProductVersion: 10.11.6
BuildVersion:   15G31
$ python --version
Python 3.5.1

まずは使ってみる

何はともあれ profile/cProfile を使ってみることにしよう。まずは Python の REPL を使って動作を確認していくことにする。

$ python

起動したら cProfile をインポートする。

>>> import cProfile

もちろん profile を使っても構わない。

>>> import profile

動作確認には time モジュールを使うことにしよう。このモジュールを使うとスレッドを一定時間停止させることができる。

>>> import time

最もシンプルな使い方としてはモジュールの run() 関数に呼び出したい Python のコードを渡す形になる。こうすると、渡した Python のコードが cProfile 経由で実行されて、プロファイリング結果が得られる。

>>> cProfile.run('time.sleep(1)')
         4 function calls in 1.001 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    1.001    1.001 <string>:1(<module>)
        1    0.000    0.000    1.001    1.001 {built-in method builtins.exec}
        1    1.001    1.001    1.001    1.001 {built-in method time.sleep}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

結果として得られる表の読み方は次の通り。

ncalls
- 呼び出し回数
tottime
- その関数の実行にかかった時間の合計
- (別の関数呼び出しにかかった時間を除く)
percall
- かかった時間を呼び出し回数で割ったもの
- (つまり 1 回の呼び出しにかかった平均時間)
cumtime
- その関数の実行にかかった時間の合計
- (別の関数呼び出しにかかった時間を含む)
filename
- lineno(function): 関数のファイル名、行番号、関数名

再帰的な処理が含まれる場合

上記の ncalls (呼び出し回数) は、再帰呼び出しがあるときとないときで表示が異なる。例えば、次のような再帰を使ってフィボナッチ数を計算する関数を用意する。

>>> def fib(n):
...     if n == 0:
...         return 0
...     if n == 1:
...         return 1
...     return fib(n - 2) + fib(n - 1)
...

これをプロファイリングにかけると 177/1 といったように分数のような表示が得られる。

>>> cProfile.run('fib(10)')
         180 function calls (4 primitive calls) in 0.000 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    177/1    0.000    0.000    0.000    0.000 <stdin>:1(fib)
        1    0.000    0.000    0.000    0.000 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 {built-in method builtins.exec}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

これは、元々は 1 回の呼び出しから関数が再帰的に 176 回呼びだされたことを意味している。右側が再帰によるものでない呼び出し回数、左側は再帰を含む呼び出し回数になっているため。

より実践的な使い方

先ほどの例では Python のコードを文字列で渡すことでプロファイリングした。とはいえ、より柔軟に一連の Python のコードをプロファイリングしたいという場合も多いはず。次は、そんなときはどうしたら良いかについて。

まずは Profile クラスのインスタンスを用意する。

>>> pr = cProfile.Profile()

そして、プロファイリングを開始するために enable() メソッドを呼びだそう。

>>> pr.enable()

その上で、プロファイリングしたいコードを実行する。

>>> fib(10)
55

そして、プロファイリングを終了するために disable() メソッドを呼び出す。

>>> pr.disable()

ちなみに、これは代わりに runcall() メソッドを使っても構わない。

>>> pr.runcall(fib, 10)
55

プロファイリングが終わったら print_stats() メソッドで結果を出力する。

>>> pr.print_stats()
         179 function calls (3 primitive calls) in 0.000 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 <stdin>:1(<module>)
    177/1    0.000    0.000    0.000    0.000 <stdin>:1(fib)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

結果を詳しく見る

これまでの例では、プロファイリングの対象となるコードがシンプルだったので結果もシンプルだった。とはいえ、実際にプロファイリングしたいようなコードは色々な処理が呼び出しあうような複雑なものになるはず。結果も自ずと重厚長大なものになるはずだ。そんなときは、プロファイリングの結果を pstats モジュールで詳しく調べることができる。

まずは pstats モジュールをインポートする。

>>> import pstats

そして、先ほどの Profile クラスのインスタンスを渡して Stats クラスをインスタンス化しよう。

>>> stats = pstats.Stats(pr)

Stats クラスのインスタンスでは、例えば特定のカラムで結果をソートできる。ここでは ncalls (呼び出し回数) で降順ソートしてみよう。

>>> stats.sort_stats('ncalls')
<pstats.Stats object at 0x102518278>

>>> stats.print_stats()
         178 function calls (2 primitive calls) in 0.000 seconds

   Ordered by: call count

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    177/1    0.000    0.000    0.000    0.000 <stdin>:1(fib)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}


<pstats.Stats object at 0x102518278>

これで、呼び出し回数の多い fib() 関数が上にくる。

プロファイリング結果をファイルに残す

プロファイリングの結果はデータとして残せるようになっていると色々と便利なはず。

そんなときは Profile クラスの dump_stats() というメソッドが使える。このメソッドは、ファイル名を指定してプロファイリング結果をファイルに保存できる。

>>> pr.dump_stats('fib.profile')

上記であれば Python の REPL を起動したディレクトリに fib.profile という名前のファイルができる。

$ ls | grep ^fib
fib.profile

上記のファイルは pstats モジュールから読み込んで使うことができる。 Stats クラスをインスタンス化するときにファイル名を文字列で指定すれば結果を読み込むことができる。

>>> import pstats
>>> stats = pstats.Stats('fib.profile')
>>> stats.print_stats()
Tue Aug 30 19:30:07 2016    fib.profile

         178 function calls (2 primitive calls) in 0.000 seconds

   Random listing order was used

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    177/1    0.000    0.000    0.000    0.000 <stdin>:1(fib)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}


<pstats.Stats object at 0x10ec9acf8>

コマンドラインでプロファイリングする

次は、そんなに使う場面はないかもしれないけどコマンドラインでプロファイリングする方法について。

例えば、次のような FizzBuzz を実行するソースコードを用意しておこう。

$ cat << 'EOF' > fizzbuzz.py
#!/usr/bin/env python
# -*- coding: utf-8 -*-


def fizzbuzz(n):
    if n % 3 == 0 and n % 5 == 0:
        return 'FizzBuzz'

    if n % 3 == 0:
        return 'Fizz'

    if n % 5 == 0:
        return 'Buzz'

    return str(n)


def main():
    for i in range(1, 100):
        message = fizzbuzz(i)
        print(message)


if __name__ == '__main__':
    main()
EOF

このソースコードは実行すると 1 から 99 までの FizzBuzz を出力する。

$ python fizzbuzz.py 
1
2
Fizz
...(省略)...
97
98
Fizz

このとき -m cProfile というオプションをつけて cProfile モジュールが実行されるようにしてみよう。これで、自動的にプロファイリングが実行される。

$ python -m cProfile fizzbuzz.py
1
2
Fizz
...(省略)...
97
98
Fizz
         202 function calls in 0.001 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.001    0.001 fizzbuzz.py:18(main)
        1    0.000    0.000    0.001    0.001 fizzbuzz.py:5(<module>)
       99    0.000    0.000    0.000    0.000 fizzbuzz.py:5(fizzbuzz)
        1    0.000    0.000    0.001    0.001 {built-in method builtins.exec}
       99    0.000    0.000    0.000    0.000 {built-in method builtins.print}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

この使い方では -s オプションを使って結果のソートができる。

$ python -m cProfile -s ncalls fizzbuzz.py
1
2
Fizz
...(省略)...
97
98
Fizz
         202 function calls in 0.001 seconds

   Ordered by: call count

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
       99    0.000    0.000    0.000    0.000 {built-in method builtins.print}
       99    0.000    0.000    0.000    0.000 fizzbuzz.py:5(fizzbuzz)
        1    0.000    0.000    0.001    0.001 fizzbuzz.py:5(<module>)
        1    0.000    0.000    0.001    0.001 fizzbuzz.py:18(main)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        1    0.000    0.000    0.001    0.001 {built-in method builtins.exec}

同じように -o オプションを使えばプロファイリング結果をファイルに保存できる。

$ python -m cProfile -o fizzbuzz.profile fizzbuzz.py
$ ls | grep .profile$
fizzbuzz.profile

呼び出し関係を調べる

profile/cProfile は処理の呼び出し回数や時間などの他に、呼び出し関係も調べることができる。例えば、先ほどの FizzBuzz のプロファイリング結果を例に使ってみよう。

まずは改めて Python の REPL を起動する。

$ python

そしてプロファイリング結果をファイル経由で読み込む。

>>> import pstats
>>> p = pstats.Stats('fizzbuzz.profile')

そして print_callers() メソッドで、呼び出し元が分かる。左が呼び出された関数で、右が呼び出し元の関数になっている。

>>> p.print_callers()
   Random listing order was used

Function                                          was called by...
                                                      ncalls  tottime  cumtime
{built-in method builtins.print}                  <-      99    0.000    0.000  fizzbuzz.py:18(main)
fizzbuzz.py:5(<module>)                           <-       1    0.000    0.001  {built-in method builtins.exec}
{built-in method builtins.exec}                   <-
{method 'disable' of '_lsprof.Profiler' objects}  <-
fizzbuzz.py:18(main)                              <-       1    0.000    0.001  fizzbuzz.py:5(<module>)
fizzbuzz.py:5(fizzbuzz)                           <-      99    0.000    0.000  fizzbuzz.py:18(main)


<pstats.Stats object at 0x100d24a58>

その逆が print_callees() メソッドで得られる。今度は左が呼び出し元で、右が呼び出し先になっている。

>>> p.print_callees()
   Random listing order was used

Function                                          called...
                                                      ncalls  tottime  cumtime
{built-in method builtins.print}                  ->
fizzbuzz.py:5(<module>)                           ->       1    0.000    0.001  fizzbuzz.py:18(main)
{built-in method builtins.exec}                   ->       1    0.000    0.001  fizzbuzz.py:5(<module>)
{method 'disable' of '_lsprof.Profiler' objects}  ->
fizzbuzz.py:18(main)                              ->      99    0.000    0.000  fizzbuzz.py:5(fizzbuzz)
                                                          99    0.000    0.000  {built-in method builtins.print}
fizzbuzz.py:5(fizzbuzz)                           ->


<pstats.Stats object at 0x100d24a58>