# cProfile でプロファイリング
どこの処理で時間がかかっているかを調べたい時に使います。 cProfile は、関数、メソッドごとに処理時間を提示してくれます。
プログラムを動かして各関数の実行時間や呼ばれた回数を記載したものをプロファイルと言います。 このプロファイルという言葉は各言語に共通です。Python に限定されません。 また、プロファイルを作成するツールを、プロファイラといいます。
プロファイル (profile) とは、
プログラムの各部分がどれだけ頻繁に呼ばれたか、 そして実行にどれだけ時間がかかったかという統計情報です。
# 1. 使い方
一見して複雑そうですが、使い方は簡単で、実行時間順にソートして、 時間がかかっているものから順に処理を速くできないかを検討していくような流れになります。
$ # cumtime で sort
$ python -m cProfile -s cumtime myscript.py
ncalls tottime percall cumtime percall filename:lineno(function)
130662 0.129 0.000 0.161 0.000 rectangle.py:1183(__and__)
3455 0.125 0.000 0.320 0.000 rectangle.py:1065(_make_rectangle_list_by_removing_inclusion)
292064 0.104 0.000 0.104 0.000 rectangle.py:1196(__le__)
7388 0.067 0.000 0.181 0.000 rectangle.py:424(_stub_rectangle_list)
...
そうやって cProfile で全体から重い箇所を抽出します。 次に特定した重い箇所は前述の timeit を使って複数の書き方を比較検討するような流れになるかなと思います。
抑えておきたいポイントは、次の３つです。 「totime と cumtime の違い」については後述します。
- ncalls が呼び出された回数であること
- totime と cumtime の２つの時間があること
- totime と cumtime の違い
# 2. 各項目の詳細
| 項目 | 説明 |
|---|---|
| ncalls | 呼び出し回数 |
| tottime | 与えられた関数に消費された合計時間 (sub-function の呼び出しで消費された時間は除外されています) |
| percall | tottime を ncalls で割った値 |
| cumtime | この関数と全ての subfunction に消費された累積時間 (起動から終了まで)。 |
| percall | cumtime をプリミティブな呼び出し回数（再帰的に呼び出されていない呼び出し回数）で割った値 |
| filename:lineno(function) | その関数のファイル名、行番号、関数名 |
ncalls に 2 つの数字が表示される時があります。そんな時は、関数、メソッドが再帰的に呼び出されている時です。 「かんたんユーザマニュアル」と書かれていますが、自分には、そんなに簡単ではなかった笑
最初の行に 2 つの数字がある場合 (たとえば 3/1) は、関数が再帰的に呼び出されたということです。 2 つ目の数字はプリミティブな呼び出しの回数で、1 つ目の数字は総呼び出し回数です。 関数が再帰的に呼び出されなかった場合、それらは同じ値で数字は 1 つしか表示されないことに留意してください。
27.4.2. かんたんユーザマニュアル (opens new window)
また、各項目の詳細は公式マニュアルにもありますが、実際のソースコードの docstring により詳細が記述されています。
# 3. totime と cumtime の違い
これを確認するために for 文を N 回使うコードを書きました。
N = 10**7
def main():
for i in range(N):
pass
a() # - -
b() # - for
c() # func -
d() # func for
def a():
pass
def b():
for i in range(N):
pass
def c():
f()
def d():
for i in range(N):
pass
f()
def f():
for i in range(N):
pass
if __name__ == '__main__':
main()
これの実行結果は次の通りです。
$ python -m cProfile sample.py
10 function calls in 1.471 seconds # <-- 総実行時間
Ordered by: standard name
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 1.471 1.471 sample.py:1(<module>)
1 0.000 0.000 0.000 0.000 sample.py:14(a)
1 0.291 0.291 0.291 0.291 sample.py:18(b)
1 0.000 0.000 0.310 0.310 sample.py:23(c)
1 0.287 0.287 0.582 0.582 sample.py:27(d)
2 0.604 0.302 0.604 0.302 sample.py:33(f)
1 0.288 0.288 1.471 1.471 sample.py:4(main)
1 0.000 0.000 1.471 1.471 {built-in method builtins.exec}
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
$
# 3.1. totime(Total time)
関数やメソッドの実行時間を引き抜いた実行時間です。 tottime を全て足し合わせると総実行時間になります。
総実行時間 = sum(tottime(関数) for 関数 in 全ての関数)
実際に足し合わせてみます。 1.471 より 0.001 秒だけ速いですが、おそらくこの理解で正しいかなと思います。
1.470 = 0.291 + 0.287 + 0.604 + 0.288
自分で書いた for, while, if 文で書いたアルゴリズムが、どのくらい時間がかかっているかがわかります。 呼び出した関数の処理時間は除かれます。
もし、tottime が大きかった場合、自分自身で書いたコードで遅いところが無いか検証します。
# 3.2. cumtime(Cumulative time)
呼び出した関数やメソッドの実行時間を含めた実行時間です。 ある関数が呼び出した関数の cumtime の総和は、その関数の cumtime になるはずです。
cumtime(ある関数)
= tottime(ある関数) + sum(
cumtime(関数) for 関数 in ある関数が呼び出した関数)
例えば関数 main は、関数 a, b, c, d を呼び出しています。 main の tottime の和と関数 a, b, c, d の cumtime の和は main の cumtime になるはずです。 今回足し合わせてみたところ 1.471 で main の cumtime と一致しました。
1.471 = 0.288 + (0.000 + 0.291 + 0.310 + 0.582)
もし、cumtime が大きかった場合、呼び出している関数、メソッドのうち処理時間が大きいものを探して改善策を検討します。
Python は関数、メソッドの呼び出しコストが大きいので、呼び出している関数、メソッドをベタ書きするだけでごくごく若干速度が改善したりします。 こことは別のところ (opens new window)で、実際に関数とベタ書きした場合の処理速度を比較しました。 ただ、可読性が悪くなるので、あまりオススメはしません。
# 4. line_profiler
行ごとのプロファイルを取ってくれる line_profiler というものがあるそうです。 使ったことがないので、名前の紹介に留めさせていただきたいと思います。 time, timeit, cProfile とは異なり標準ライブラリにはないので pip install する必要があります。
# 5. 終わりに
これで実行時間の計測の仕方は以上になります。 プロファイラを知らなくて自作しようと暴走したり timeit の最適化の罠にハマったりで大変でした笑 もしなにかしらのお力添えになっていれば幸いです。 ありがとうございました。