プログラムの実行速度が気になるとき、まず行うべきことは実行時間計測である。
この連載ではあえてここまで書かなかったが、もうCythonにも慣れてきたであろうから、普通に実行時間計測をしよう。
実行時間計測であるが、今まではプログラムの2点で時間計測を行い、その差をその間の部分を実行するのに掛かった時間とみなした。
これでも実行時間計測であるが、もっとプログラム全体のどこで時間を食っているかを知りたいものである。
プロファイラ(プロフィール)というのが多くのプログラミング言語で用意されており、それを実行することで、プログラムの各部、つまり各関数が何回呼ばれて、どれだけ時間が掛かったが表示される。う
プロファイラ
たとえば、Julia集合のPython版である julia_py.py のプロファイルは、次のように実行できる。
-s tottime は、結果の出力がトータル実行時間の多い順にソートすることを指定している。
$ python3 -m cProfile -s tottime julia_py.py
time=33.38639044761658ここで、Julia集合が表示されるが、表示を閉じる（プログラムが終わる）と、プロファイルの結果が示される。
94877942 function calls (94860635 primitive calls) in 47.635 seconds
Ordered by: internal time
ncalls tottime percall cumtime percall filename:lineno(function)
91361955 16.916 0.000 16.916 0.000 julia_py.py:19(norm2)
1002001 16.030 0.000 32.947 0.000 julia_py.py:11(escape)
1 12.643 12.643 13.004 13.004 {built-in method exec}
1 0.440 0.440 33.386 33.386 julia_py.py:22(calc_julia)
32049 0.186 0.000 0.309 0.000 inspect.py:625(cleandoc)
1 0.126 0.126 0.127 0.127 backend_qt.py:100(_create_qApp)
1 0.056 0.056 0.057 0.057 {built-in method show}
3 0.050 0.017 0.050 0.017 {method 'take' of 'numpy.ndarray' objects}
8612 0.043 0.000 0.108 0.000 inspect.py:2124(_signature_from_function)計算にかかったトータルの時間は、コマンド直後の行に、time=33.38639044761658と表示されている。
関数毎に、
呼び出し回数、トータル時間、、、、ファイル名:行番号(関数名)
の形式で表示されている。
julia_py.pyがJulia集合のPythonのプログラムである。
inspect.pyがあるが、これはマニュアルによると、活動中のオブジェクトから情報を得るために呼び出されるとある。
トータル時間順にソートされていて、この表は延々と続くので、先頭部分だけを示している。
最初の2つが、16.916秒と16.030秒であり、この合計だけで32.946秒になり、全体の実行時間33.386秒であり、全体の98.7％の時間を食っている。
ということで、高速化すべきは、この２つの関数norm2とescapeだと分かる。
これらをCython化(型宣言)したjulia_cy5.pyxを使って、実行時間計測をしてみよう。
from julia_cy5 import julia
if __name__ == '__main__':
julia()テスト用に、上記のファイルを用意した。
関数julia()は、julia_cy5.pyx のものをそのまま使う。
julia $ python3 -m cProfile -s tottime julia_cy5_main.py
time=0.01784229278564453
2380476 function calls (2364472 primitive calls) in 2.723 seconds
Ordered by: internal time
ncalls tottime percall cumtime percall filename:lineno(function)
1 1.335 1.335 1.500 1.500 {built-in method exec}
32049 0.186 0.000 0.308 0.000 inspect.py:625(cleandoc)
1 0.109 0.109 0.109 0.109 backend_qt.py:100(_create_qApp)
1 0.056 0.056 0.057 0.057 {built-in method show}
3 0.042 0.014 0.042 0.014 {method 'take' of 'numpy.ndarray' objects}
8612 0.042 0.000 0.106 0.000 inspect.py:2124(_signature_from_function)
2 0.036 0.018 0.036 0.018 {built-in method matplotlib._image.resample}
34/33 0.034 0.001 0.037 0.001 {built-in method _imp.create_dynamic}
282 0.031 0.000 0.031 0.000 {built-in method marshal.loads}実行できて、Julia集合の画像も出てきて、それを閉じるとcProfileの結果が出てきた。しかし、norm2やescapeの関数名が見当たらない。それに、そもそも、ファイル名の julia_cy5.pyxが見当たらない。高速になりすぎて、表示されなくなったのだろうか。
そうではなくて、julia_cy5.pyxのコンパイルがprofileに対応していなかったからのようだ。
ということで、先頭に次の行を挿入した。
# cython: profile=True$ python3 -m cProfile -s tottime julia_cy5_main.py
time=0.017809391021728516
2386863 function calls (2370833 primitive calls) in 2.977 seconds
Ordered by: internal time
ncalls tottime percall cumtime percall filename:lineno(function)
1 1.545 1.545 1.734 1.734 {built-in method exec}
32049 0.193 0.000 0.319 0.000 inspect.py:625(cleandoc)
1 0.110 0.110 0.110 0.110 backend_qt.py:100(_create_qApp)
1 0.057 0.057 0.058 0.058 {built-in method show}
3 0.047 0.016 0.047 0.016 {method 'take' of 'numpy.ndarray' objects}
8612 0.043 0.000 0.108 0.000 inspect.py:2124(_signature_from_function)
2 0.038 0.019 0.038 0.019 {built-in method matplotlib._image.resample}
34/33 0.036 0.001 0.038 0.001 {built-in method _imp.create_dynamic}
510834/509694 0.032 0.000 0.032 0.000 {built-in method builtins.len}
282 0.031 0.000 0.031 0.000 {built-in method marshal.loads}
196553 0.030 0.000 0.030 0.000 {built-in method builtins.min}
1172/1001 0.025 0.000 0.735 0.001 {built-in method builtins.__build_class__}
297371 0.025 0.000 0.025 0.000 {method 'lstrip' of 'str' objects}
8755/8719 0.024 0.000 0.153 0.000 inspect.py:2218(_signature_from_callable)
23413 0.023 0.000 0.041 0.000 inspect.py:2489(__init__)
216 0.023 0.000 0.313 0.001 artist.py:1422(get_setters)
1 0.022 0.022 0.022 0.022 {built-in method sizeHint}
33099 0.020 0.000 0.342 0.000 inspect.py:606(getdoc)
38012 0.019 0.000 0.019 0.000 {method 'split' of 'str' objects}
1 0.018 0.018 0.018 0.018 julia_cy5.pyx:32(calc_julia)
8828 0.017 0.000 0.027 0.000 inspect.py:2772(__init__)
9093 0.016 0.000 0.016 0.000 {method 'search' of 're.Pattern' objects}
434 0.016 0.000 0.016 0.000 {built-in method builtins.dir}
80175 0.016 0.000 0.016 0.000 {built-in method builtins.getattr}
144447 0.015 0.000 0.019 0.000 {built-in method builtins.isinstance}プロファイル結果なのだが、なぜか関数escapeとnorm2が存在しない。
関数calc_juliaは一度呼ばれて、totime とcumtime(累積時間)が共に0.018になっている。calc_juliaは延々とescapeを呼び、escapeは発散するまで延々とnorm2を呼び出す。
だから、tottimeは非常に小さな値でなければいけないが、tottimeに、その下位の関数の実行時間が全部足し合わされているようである。
関数escapeとnorm2は、nogil属性がついているので、対応できないのかも知れない。
ということで、並列処理のためにnogil属性をつける直前のjulia_cy4.pyxに
# cython: profile=Trueを加えて、setup.pyを実行することでコンパイルした。
そして、julia_cy4_main.pyを作って、実行した。
from julia_cy4 import julia
if __name__ == '__main__':
julia()$ python3 -m cProfile -s tottime julia_cy4_main.py
time=10.272151231765747
94749161 function calls (94733119 primitive calls) in 14.030 seconds
Ordered by: internal time
ncalls tottime percall cumtime percall filename:lineno(function)
1002001 6.841 0.000 10.132 0.000 julia_cy4.pyx:15(escape)
91361955 3.291 0.000 3.291 0.000 julia_cy4.pyx:25(norm2)
1 2.318 2.318 2.505 2.505 {built-in method exec}
32049 0.189 0.000 0.314 0.000 inspect.py:625(cleandoc)
1 0.140 0.140 10.272 10.272 julia_cy4.pyx:28(calc_julia)
1 0.127 0.127 0.128 0.128 backend_qt.py:100(_create_qApp)
1 0.060 0.060 0.061 0.061 {built-in method show}
3 0.049 0.016 0.049 0.016 {method 'take' of 'numpy.ndarray' objects}
282 0.044 0.000 0.044 0.000 {built-in method marshal.loads}
8612 0.044 0.000 0.110 0.000 inspect.py:2124(_signature_from_function)今度は、ちゃんとescapeとnorm2が表示されている。
escapeは、1001×1001=1002001回呼び出されている。トータルで6.8秒だから、１回あたり6.8マイクロ秒となる。
norm2は、そのさらに91倍呼び出されている。これは、発散するまでに平均91回計算が行われたことを示す。
ということで、ここでも、実行時間time=10.272の大部分がこの２つの関数で食われていたことが分かる。
色々分かって助かった、と思うのは早い。
Cython(12)で実行した時の結果が次である。
In [1]: import julia_cy４
In [2]: julia_cy4.julia()
time=0.321358680725097660.321秒でできていた計算が、プロファイラで計測すると10.272秒かかるようになっている。30倍も遅くなっている。
なぜ？？？
プロファイラのオーバーヘッド
プロファイラを動かすと、実行の途中で色々記録を取らなくてはならず、その量が非常に多くなる。本来の計算よりも、プロファイラの実行時間の方がはるかに大きくなっているようだ。
関数の相対的な実行時間は分かるが、絶対的な時間は計測による遅延の方が大きくなることがあるので、そのあたりは考えて使おう。
実際にcProfileを使うのは、かなり大きなプログラムで、それも自分が作ったのではないプログラムの速度改善を考える場合が多い。
オールPython版の場合は、計測遅延の影響が少ないが、Cython化を進めて高速になったものの実行時間計測をするときには、計測遅延を考慮しよう。
記事のサンプルプログラムでの性能向上は、プログラムが短すぎて現実的ではない。数千行、あるいはそれ以上に長いプログラムと戦わなければいけない場合について書くのは難しい。
高速化するときには、かならず性能評価ツールを使おう。
cProfileなどを使って効率よくピンポイントでボトルネックを探すべきである。
感に頼ったボトルネック探しは効率悪く、見逃す可能性も高い。
性能以外に、そのプログラムの様々な性質(profile)が見えてくることもある。
＃人気の記事
＃タグ
