Python コードのプロファイリング

2016年2月14日

はじめに

Python コードのプロファイリングについて、Micha Gorelick, Ian Ozsvald 著 "ハイパフォーマンス Python" の内容を実際に試してみたメモ。

環境

  • Intel Core i5 M450 2.4 GHz
  • Windows 7 64 bit
  • MSYS2 64 bit (MinGW w64)
  • Anaconda for Windows (Python 2.7)

※MinGW にも Python が入っているので、Anaconda のほうを使うようにパスを設定している。

サンプルコード

サンプルコードは こちら から入手。

ここでは以下のものを用いる。

01_profiling/cpu_profiling

  • julia1.py
  • julia1_nopil.py (画像表示なし)

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)

cProfile

cProfile というモジュールで、関数ごとの実行時間のリストを得ることができる。

$ 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}

それぞれの項目は順番に以下の通りである。

  • ncalls: 関数が呼ばれた回数
  • tottime: 関数でかかった全時間
  • percall: 関数 1 回分の時間
  • cumtime: 関数が呼んだ関数の時間まで含めた累積時間
  • percall: 関数 1 回分の累積時間

オプション "-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_profiler

line_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_profiler

memory_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() は、たぶんグラフを見やすくするために入れてある。この結果をプロットすると、次のようになる。

参考文献