Python: line_profiler でボトルネックを調べる

前回は Python の標準ライブラリに用意されているプロファイラの profile/cProfile モジュールについて書いた。

blog.amedama.jp

今回は、同じ決定論的プロファイリングを採用したプロファイラの中でも、サードパーティ製の line_profiler を使ってみることにする。 line_profiler は profile/cProfile モジュールに比べるとコード単位でプロファイリングが取れるところが魅力的なパッケージ。また、インターフェースについても profile/cProfile に近いものとなっている。

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

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

インストール

まずは line_profiler をインストールする。サードパーティ製のパッケージなので pip を使う。

$ pip install line_profiler

題材とするプログラム

ひとまず、前回も使った 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

プロファイリングしてみる

さて、それでは用意したソースコードを早速プロファイリングしてみよう。

ここでは Python の REPL を使って動作を確認していく。先ほどのソースコードを用意したのと同じディレクトリで REPL を起動しよう。

$ python

REPL が起動したら、まずはプロファイリング対象の fizzbuzz モジュールをインポートしておく。補足しておくと Python ではソースコード (*.py) が、そのままモジュールに対応している。例えば先ほどの fizzbuzz.py であれば fizzbuzz モジュールとして使えるわけだ。

>>> import fizzbuzz

続いて line_prpfiler モジュールをインポートして LineProfiler クラスのインスタンスを生成しよう。このインスタンスを使ってプロファイリングをする。

>>> import line_profiler
>>> pr = line_profiler.LineProfiler()

プロファイリング対象の関数を LineProfiler#add_function() メソッドを使って登録しよう。ここでは、前述の fizzbuzz モジュールの中にある fizzbuzz 関数を登録した。

>>> pr.add_function(fizzbuzz.fizzbuzz)

そして、続いて LineProfiler#runcall() メソッドでプロファイリングを実行する。このメソッドで実行した処理の中で、先ほど LineProfiler#add_function() メソッドで登録した関数が呼び出されることを期待する。もし呼びだされた場合には、それが処理される過程が line_profiler によって逐一記録されるという寸法だ。

>>> pr.runcall(fizzbuzz.main)
1
2
Fizz
...(省略)...
97
98
Fizz

ちなみに、上記の LineProfiler#runcall() メソッドは、代わりに次のようにしても構わない。こちらのやり方では LineProfiler#enable() メソッドと LineProfiler#disable() メソッドによってプロファイリングのオン・オフを切り替えている。 LineProfiler#enable() メソッドと LineProfiler#disable() メソッドの間に実行された処理がプロファイリングの対象ということになる。

>>> pr.enable()
>>> fizzbuzz.main()
1
2
Fizz
...(省略)...
97
98
Fizz
>>> pr.disable()

プロファイリングが終わったら LineProfiler#print_stats() メソッドで結果を表示しよう。すると、次のようにプロファイリング結果が得られる。

>>> pr.print_stats()
Timer unit: 1e-06 s

Total time: 0.000292 s
File: /Users/amedama/Documents/temporary/fizzbuzz.py
Function: fizzbuzz at line 5

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     5                                           def fizzbuzz(n):
     6        99           95      1.0     32.5      if n % 3 == 0 and n % 5 == 0:
     7         6            0      0.0      0.0          return 'FizzBuzz'
     8
     9        93           57      0.6     19.5      if n % 3 == 0:
    10        27           13      0.5      4.5          return 'Fizz'
    11
    12        66           46      0.7     15.8      if n % 5 == 0:
    13        13           29      2.2      9.9          return 'Buzz'
    14
    15        53           52      1.0     17.8      return str(n)

上記の表のカラムは次のような意味がある。

Line
- ソースコードの行番号
Hits
- その行が実行された回数
Time
- その行の実行に費やした時間の合計
- 単位は先頭行の Timer unit で示されている
Per Hit
- その行を 1 回実行するのに費やした時間
% Time
- その行の実行に費やした時間の全体に対する割合
Line Contents
- 行番号に対応するソースコード

とても分かりやすい。

コマンドラインから調べる

line_profiler には、もうひとつコマンドラインからプロファイリングを実行するインターフェースがある。むしろ、公式の説明を見るとこちらを推している雰囲気がある。ただ、個人的には先ほどのやり方が便利なので、こちらをあまり使うことはないかな…という感じ。

コマンドラインからの処理では、まずプロファイリングを実行したい関数に一工夫が必要になる。具体的には、プロファイリングを実行したい関数やメソッドを @profile デコレータで修飾する。

以下は fizzbuzz() 関数に @profile デコレータをつけたサンプルコード。

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


@profile
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

ちなみに、するどい人は上記が @profile デコレータがインポートされていないのでエラーになると気づくかもしれない。

その通りで、実はこのソースコードは通常の Python インタプリタでは実行できなくなる。

$ python fizzbuzz.py 
Traceback (most recent call last):
  File "fizzbuzz.py", line 5, in <module>
    @profile
NameError: name 'profile' is not defined

ただ、line_profiler を使ってコマンドラインでプロファイリングするときは専用のコマンドを使うことになる。具体的には kernprof というコマンドを使う。このコマンドではソースコードの中の @profile デコレータがちゃんと動作するように細工して実行するので問題ない。

早速 kernprof コマンドで fizzbuzz.py をプロファイリングしてみよう。

$ kernprof -l fizzbuzz.py
1
2
Fizz
...(省略)...
97
98
Fizz
Wrote profile results to fizzbuzz.py.lprof

実行すると、プロファイリング対象のファイル名に .lprof という拡張子のついたファイルができる。

そして、そのできたファイルを line_profiler モジュールをコマンドライン経由で読み込ませる。すると、解析結果が表示される。

$ python -m line_profiler fizzbuzz.py.lprof
Timer unit: 1e-06 s

Total time: 0.000275 s
File: fizzbuzz.py
Function: fizzbuzz at line 5

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     5                                           @profile
     6                                           def fizzbuzz(n):
     7        99          116      1.2     42.2      if n % 3 == 0 and n % 5 == 0:
     8         6            3      0.5      1.1          return 'FizzBuzz'
     9
    10        93           53      0.6     19.3      if n % 3 == 0:
    11        27           15      0.6      5.5          return 'Fizz'
    12
    13        66           33      0.5     12.0      if n % 5 == 0:
    14        13            5      0.4      1.8          return 'Buzz'
    15
    16        53           50      0.9     18.2      return str(n)