cProfileを使ってPythonでの計算時間を測定する

最近は，4回生になり研究室に配属されて画像処理の勉強をしています．論文を読んでそれを実装してみるという流れで勉強していますが，REPLでnumpyの行列計算のコードを打っていると，目立って時間がかかる行があることが分かります．そこで，繰り返し呼ぶ処理や重い処理にかかる時間を，定量的に調べたいと思いました．

やりたいこと

スクリプト全体で，時間がかかっている箇所を調べたい
遅い処理を見つけて高速化したい
できるだけ簡単にプロファイリングしたい

環境・使用ライブラリ

Ubuntu 16.04.4 LTS
- WSL上で動かしています
Python 3.5.2
cPofile
pstats

Pythonで使えるプロファイラについて調べてみると，cProfileとline_profilerという2つのプロファイラがあることが分かりました． line_profilerを使う場合は関数に@profileというデコレータを追加する必要があり，コードを書き換えずにREPLで試したいので今回はパスしました．Pythonに標準で入っているcProfileを使うことにしました．pstatsはプロファイリング結果を表示できるモジュールです．

方法

時間を計測したいコードの前に以下のコードを貼り付けて，プロファイラを有効にします．

import cProfile
import pstats
c_profile = cProfile.Profile()
c_profile.enable()

計測したいコードの後に以下のコードを貼り付けます． print_stats(10)はtottime(そのメソッドにかかった時間の合計)の上位10個をとってくるという意味です．

c_profile.disable()
c_stats = pstats.Stats(c_profile)
c_stats.sort_stats('tottime').print_stats(10)

全体をプロファイラにかける

結果

書いていたスクリプト(本来は貼るべきですが，説明すると長くなりそうなので省略)をプロファイラにかけると，6.8秒もかかっていて，そのうちのほとんどがnumpy/linalg/linalg.py:1299(svd)にかかっていることが分かりました．

        267323 function calls (261982 primitive calls) in 6.844 seconds

   Ordered by: internal time
   List reduced from 2743 to 10 due to restriction <10>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    4.634    4.634    4.634    4.634 /usr/local/lib/python3.5/dist-packages/numpy/linalg/linalg.py:1299(svd)
        1    1.082    1.082    1.082    1.082 {built-in method numpy.core.multiarray.matmul}
       16    0.195    0.012    0.195    0.012 {imread}
       28    0.116    0.004    0.121    0.004 {built-in method _imp.create_dynamic}
      286    0.083    0.000    0.099    0.000 <frozen importlib._bootstrap_external>:816(get_data)
        1    0.078    0.078    5.793    5.793 /usr/local/lib/python3.5/dist-packages/numpy/linalg/linalg.py:1652(pinv)
      286    0.062    0.000    0.062    0.000 {built-in method marshal.loads}
1273/1218    0.027    0.000    0.119    0.000 {built-in method builtins.__build_class__}
     1269    0.022    0.000    0.022    0.000 {built-in method posix.stat}
      286    0.016    0.000    0.016    0.000 {method 'read' of '_io.FileIO' objects}

考察

コード中に x = np.dot( np.linalg.pinv(A) , b) という部分があり，そこがnp.linalgを使っていたので遅そうだと考えました．この部分はこの記事の本題とは関係ありませんが， $A {\bf x} = {\bf b}$ を解いています．優決定系(変数の数より連立方程式の数が多い)の行列で最小二乗誤差が小さくなるようなxを求める式です．詳しくはこちらのサイトに書いてあります．

最小二乗法とフィッティングとモデルパラメータ推定（アマチュア用）

行列計算を改善する

先ほど遅かった部分の計算時間を見るために，次のコードをREPLに貼り付けました．

import cProfile
import pstats
c_profile = cProfile.Profile()
c_profile.enable()

x = np.dot( np.linalg.pinv(A) , b)

c_profile.disable()
c_stats = pstats.Stats(c_profile)
c_stats.sort_stats('tottime').print_stats(10)

結果

         51 function calls in 5.461 seconds

   Ordered by: internal time
   List reduced from 29 to 10 due to restriction <10>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    4.353    4.353    4.353    4.353 /usr/local/lib/python3.5/dist-packages/numpy/linalg/linalg.py:1299(svd)
        1    1.026    1.026    1.026    1.026 {built-in method numpy.core.multiarray.matmul}
        1    0.079    0.079    5.458    5.458 /usr/local/lib/python3.5/dist-packages/numpy/linalg/linalg.py:1652(pinv)
        1    0.003    0.003    0.003    0.003 {built-in method numpy.core.multiarray.dot}
        1    0.000    0.000    0.000    0.000 {method 'reduce' of 'numpy.ufunc' objects}
        3    0.000    0.000    0.000    0.000 /usr/local/lib/python3.5/dist-packages/numpy/core/numeric.py:424(asarray)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.5/dist-packages/numpy/core/fromnumeric.py:2222(amax)
        3    0.000    0.000    0.000    0.000 {built-in method numpy.core.multiarray.array}
        3    0.000    0.000    0.000    0.000 {method 'astype' of 'numpy.ndarray' objects}
        1    0.000    0.000    0.000    0.000 <stdin>:1(<module>)

考察

ここでやはり4秒程度かかっていたことが分かります．これまでは， $A {\bf x} = {\bf b}$ を解くときに[tex: A^T A {\bf x} = A^T {\bf b}] から疑似逆行列(np.linalg.pinv(A))を求めて[tex: {\bf x} = (A^T A)^{-1} A^T {\bf b}] を計算して解いていました．それをやめて，lstsqという最小二乗法のメソッドを使ってnp.linalg.lstsq(A.T @ A, A.T @ b)とする方が効率的かもしれないと思いました．

改善して比較する

先ほどと比較するために，次のコードをREPLに貼り付けました．

import cProfile
import pstats
c_profile = cProfile.Profile()
c_profile.enable()

AT =A.T
x,res,rank,s = np.linalg.lstsq(AT @ A, AT @ b)

c_profile.disable()
c_stats = pstats.Stats(c_profile)
c_stats.sort_stats('tottime').print_stats(10)

結果

         122 function calls in 0.389 seconds

   Ordered by: internal time
   List reduced from 46 to 10 due to restriction <10>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        2    0.383    0.192    0.383    0.192 {built-in method numpy.linalg.lapack_lite.dgelsd}
        2    0.003    0.002    0.003    0.002 {built-in method numpy.core.multiarray._fastCopyAndTranspose}
        1    0.001    0.001    0.001    0.001 {method 'write' of '_io.TextIOWrapper' objects}
        8    0.000    0.000    0.000    0.000 {built-in method posix.stat}
        1    0.000    0.000    0.389    0.389 /usr/local/lib/python3.5/dist-packages/numpy/linalg/linalg.py:1880(lstsq)
        5    0.000    0.000    0.000    0.000 {built-in method numpy.core.multiarray.zeros}
        1    0.000    0.000    0.000    0.000 /usr/lib/python3.5/linecache.py:82(updatecache)
        1    0.000    0.000    0.002    0.002 {built-in method _warnings.warn}
        7    0.000    0.000    0.000    0.000 /usr/lib/python3.5/posixpath.py:71(join)
        1    0.000    0.000    0.000    0.000 {method 'reduce' of 'numpy.ufunc' objects}

は，速い・・・

考察

4秒以上かかっていた先ほどと比べて，0.389秒とかなり速くなっていることが分かりました．

感想

REPLでもプロファイラを使って実行時間を比較できることが分かりました．処理が遅いときに原因となっている箇所を探すのに使えそうです． CliborやClipyのスニペットに追加しておくと便利そうだと思いました．メソッドごとに見られるline_profilerも便利そうなので，cProfileに飽きてきたらそちらも使ってみようと思います．