Python コードのプロファイリング2016年2月14日 | |
はじめにPython コードのプロファイリングについて、Micha Gorelick, Ian Ozsvald 著 "ハイパフォーマンス Python" の内容を実際に試してみたメモ。 環境
※MinGW にも Python が入っているので、Anaconda のほうを使うようにパスを設定している。 サンプルコードサンプルコードは こちら から入手。 ここでは以下のものを用いる。 01_profiling/cpu_profiling
juli1.py で画像をグレースケールで描画する場合は show_greyscale() を、そうでなければ show_false_greyscale() を用いる。画像ファイルを保存したい場合は、これらの関数の表示の部分を以下のように書き換える。 #im.show() im.save("julia.png") 計算時間の測定Python コード内で時間を計測するには、つぎのようにする。 import time start_time = time.time() ... end_time = time.time() elapsed_time = end_time - start_time print("Elapsed Time: %f s" % elapsed_time) MinGW の time コマンドを使ってもよい。 サンプルコード "julia1_nopil.py" の実行結果は以下の通りである (MSYS2 で実行)。 $ time python julia1_nopil.py Length of x: 1000 Total elements: 1000000 calculate_z_serial_purepython took 12.8117320538 seconds real 0m13.787s user 0m0.000s sys 0m0.015s デコレータの使用デコレータというものを使うと、関数に時間計測の処理を楽に指定できる。 import time from functools import wraps def time_func(func): @wraps(func) def measure_time(*args, **keywords): t1 = time.time() result = func(*args, **keywords) t2 = time.time() print("@time_func: " + func.func_name + " took " + str(t2 - t1) + " seconds") return result return measure_time 時間計測を行わせたい関数の前に "@time_func" を付ける。 @time_func def calculate_z_serial_purepython(maxiter, zs, cs): ... 実行結果は以下の通り。 $ python julia1_nopil_decorate.py Length of x: 1000 Total elements: 1000000 @time_func: calculate_z_serial_purepython took 12.6167221069 seconds calculate_z_serial_purepython took 12.6177220345 seconds timeit モジュールの利用timeit モジュールというもので時間を計測することもできる。たとえば、以下のように実行する。 $ python -m timeit -n 5 -r 5 -s "import julia1_nopil" "julia1_nopil.calc_pure_python(False, 1000, 300)" Length of x: 1000 Total elements: 1000000 calculate_z_serial_purepython took 12.3917081356 seconds Length of x: 1000 Total elements: 1000000 calculate_z_serial_purepython took 12.4317109585 seconds ... 5 loops, best of 5: 13.2 sec per loop オプション "-n" は指定した文を何回実行するか、"-r" は何回繰り返すかを指定する。"-s" は初めに 1 回だけ実行される文である。"-n 5 -r 5" だと、"-n" で指定した 5 回で平均値を取って、それを "-r" で指定した 5 回だけ繰り返し、その中の最小値を最後に表示する。 "-n" を 5、"-r" を 3 とすると以下のような結果になる。 5 loops, best of 3: 13.2 sec per loop IPython だと同じことを以下のように行える。 In [1]: import julia1_nopil In [2]: %timeit -n 5 -r 5 julia1_nopil.calc_pure_python(False, 1000, 300) cProfilecProfile というモジュールで、関数ごとの実行時間のリストを得ることができる。 $ python -m cProfile -s cumulative julia1_nopil.py Length of x: 1000 Total elements: 1000000 calculate_z_serial_purepython took 15.2958748341 seconds 36221992 function calls in 16.403 seconds Ordered by: cumulative time ncalls tottime percall cumtime percall filename:lineno(function) 1 0.056 0.056 16.403 16.403 julia1_nopil.py:1(<module>) 1 0.870 0.870 16.347 16.347 julia1_nopil.py:23(calc_pure_python) 1 11.780 11.780 15.295 15.295 julia1_nopil.py:9(calculate_z_serial_purepython) 34219980 3.498 0.000 3.498 0.000 {abs} 2002000 0.170 0.000 0.170 0.000 {method 'append' of 'list' objects} 1 0.018 0.018 0.018 0.018 {range} 1 0.012 0.012 0.012 0.012 {sum} 2 0.000 0.000 0.000 0.000 {time.time} 4 0.000 0.000 0.000 0.000 {len} 1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects} それぞれの項目は順番に以下の通りである。
オプション "-s" はソーティングオプションで、"cumulative" は累積時間 (cumtime) によるソートの指定である。他に "name" で名前順、"time" で関数の全時間 (tottime) 順である。 プロファイル結果をファイルに書き出すには次のようにする。 $ python -m cProfile -o profile.stats julia1_nopil.py 情報を表示するには Python で次のようにする。 $ winpty python >>> import pstats >>> p = pstats.Stats("profile.stats") >>> p.sort_stats("cumulative") >>> p.print_stats() ... ここで "winpty" は MSYS2 (mintty) で Python を対話式で実行するのに必要なものである。 次のようにすると、関数ごとの呼び出し側一覧が得られる。 >>> p.print_callers() 次のようにすると、上記の逆の一覧が得られる。 >>> p.print_callees() line_profilerline_profiler を用いると、行単位でプロファイリングできる。まず、line_profiler を pip でインストールする。 $ pip install line_profiler 以下のようなエラーが出た。 error: Microsoft Visual C++ 9.0 is required (Unable to find vcvarsall.bat).Get it from http://aka.ms/vcpython27 示されている URL をブラウザに入力すると、"Microsoft Visual C++ Compiler for Python 2.7" のページに行く。ここから Visual C++ Compiler for Python 2.7 をダウンロードして、インストールする。再度 line_profiler のインストールを行うと、正常に終了する。 プロファイルを行いたい関数の前に "@profile" をつける。 @profile def calculate_z_serial_purepython(maxiter, zs, cs): ... 以下のように実行する。 $ kernprof -l -v julia1_nopil_line_profiler.py Length of x: 1000 Total elements: 1000000 calculate_z_serial_purepython took 157.629000187 seconds Wrote profile results to julia1_nopil_line_profiler.py.lprof Timer unit: 4.27732e-07 s Total time: 89.9634 s File: julia1_nopil_line_profiler.py Function: calculate_z_serial_purepython at line 9 Line # Hits Time Per Hit % Time Line Contents ============================================================== 9 @profile 10 def calculate_z_serial_purepython(maxiter, zs, cs): 11 """Calculate output list using Julia update rule""" 12 1 15330 15330.0 0.0 output = [0] * len(zs) 13 1000001 1721246 1.7 0.8 for i in range(len(zs)): 14 1000000 1504051 1.5 0.7 n = 0 15 1000000 1696994 1.7 0.8 z = zs[i] 16 1000000 1677359 1.7 0.8 c = cs[i] 17 34219980 79319823 2.3 37.7 while abs(z) < 2 and n < maxiter: 18 33219980 66539799 2.0 31.6 z = z * z + c 19 33219980 55919248 1.7 26.6 n += 1 20 1000000 1932494 1.9 0.9 output[i] = n 21 1 25 25.0 0.0 return output オプション "-l" が行ごとのプロファイルを行う指示である。"-v" は冗長出力で、これを指定しない場合は、.lprof ファイルが出力される。.lprof ファイルを用いる場合は、次のように実行すると、上記と同様の出力を得ることができる。 $ python -m line_profiler julia1_nopil_line_profiler.py.lprof memory_profilermemory_profiler を用いると、メモリの使用状況を知ることができる。line_profiler 同様、プロファイルを行いたい関数の前に "@profile" をつける。 @profile def calculate_z_serial_purepython(maxiter, zs, cs): ... 以下のように実行する。 $ python -m memory_profiler julia1_nopil_memory_profiler.py Length of x: 300 Total elements: 90000 calculate_z_serial_purepython took 289.967000008 seconds Filename: julia1_nopil_memory_profiler.py Line # Mem usage Increment Line Contents ================================================ 9 34.867 MiB 0.000 MiB @profile 10 def calculate_z_serial_purepython(maxiter, zs, cs): 11 """Calculate output list using Julia update rule""" 12 35.551 MiB 0.684 MiB output = [0] * len(zs) 13 37.152 MiB 1.602 MiB for i in range(len(zs)): 14 37.152 MiB 0.000 MiB n = 0 15 37.152 MiB 0.000 MiB z = zs[i] 16 37.152 MiB 0.000 MiB c = cs[i] 17 37.152 MiB 0.000 MiB while abs(z) < 2 and n < maxiter: 18 37.152 MiB 0.000 MiB z = z * z + c 19 37.152 MiB 0.000 MiB n += 1 20 37.152 MiB 0.000 MiB output[i] = n 21 37.148 MiB -0.004 MiB return output 実行にものすごく時間がかかるので、計算範囲を 300x300 にしている。 mprof を使うと、メモリの使用量の時間変化のグラフを得ることができる。以下のように実行。 $ mprof run julia1_nopil_memory_profiler.py 以下のコマンドでグラフが表示される。 $ mprof plot ![]() プロファイルデータが保存されているので、ファイルを指定すればそれをプロットしてくれる。指定なしだと最新のデータがプロットされる。 $ mprof plot mprofile_20160206151837.dat グラフにラベルを付けることができる。プログラムを次のように変更する。 @profile def calculate_z_serial_purepython(maxiter, zs, cs): """Calculate output list using Julia update rule""" with profile.timestamp("create_output_list"): output = [0] * len(zs) time.sleep(0.1) with profile.timestamp("create_range_of_zs"): iterations = range(len(zs)) with profile.timestamp("calculate_output"): for i in iterations: n = 0 z = zs[i] c = cs[i] while abs(z) < 2 and n < maxiter: z = z * z + c n += 1 output[i] = n return output ここで、time.sleep() は、たぶんグラフを見やすくするために入れてある。この結果をプロットすると、次のようになる。 ![]() 参考文献 | |
PENGUINITIS |