プロファイリングとは
- 必要十分なスピードと無駄のないリソース使用量でコードを実行するためにボトルネックになっている処理を特定すること
- python用の有名なツール
- Pythonとtimeit
- cProfile
- line_profiler
- memory_profiler
ツールの紹介
IPythonとtimeit
- python対話型インタンプリタの拡張版
- timeitモジュールでテスト回数（-r）、ループ回数（-n）を指定して平均実行時間を計測
- 短いコードを直接実行とコードファイルをインポートして実行の2パターンがある
インストール
pip install ipython
サンプルコード
profiling.py
def fn_arr():
for i in range(1000): arr.append(i)
def fn_ls():
for i in range(1000): ls.append(i)
測定
シングルコードの実行
ipython
In [1]:from array import array
In [2]:arr = array('I', [])
In [3]:%timeit -r 10 -n 10 for i in range(1000): arr.insert(0, i)
10 loops, best of 10: 3.02 ms per loop
In [4]:%timeit -r 10 -n 10 for i in range(1000): ls.insert(0, i)
10 loops, best of 10: 3.8 ms per loop
ファイルを実行
ipython
In [1]: from profiling import fn_arr
In [2]: from profiling import fn_ls
In [3]: %timeit -r 10 -n 10 fn_arr()
10 loops, best of 10: 68.6 µs per loop
In [4]: %timeit -r 10 -n 10 fn_ls()
10 loops, best of 10: 8.92 µs per loop
10回のループ処理を10回実行した時の1ループあたりの平均実行時間を取得
cProfile
- 標準のプロファイリングツール
- 実行する全ての関数の実行時間を測定
サンプルコード
profiling.py
def fn():
l = []
for _ in range(1000000):
l.append('hoge')
l.pop()
fn()
測定
ファイルを指定して実行
python -m cProfile -s cumulative index.py
2000004 function calls in 23.897 seconds
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 23.897 23.897 {built-in method exec}
1 0.000 0.000 23.897 23.897 index.py:1(<module>)
1 12.231 12.231 23.897 23.897 index.py:3(fn)
1000000 5.833 0.000 5.833 0.000 {method 'append' of 'list' objects}
1000000 5.832 0.000 5.832 0.000 {method 'pop' of 'list' objects}
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
測定結果を出力
python -m cProfile -o profile.stats index.py
測定結果ファイルを読み込んで表示
python
>>> import pstats
>>> p = pstats.Stats('profile.stats')
>>> p.sort_stats('cumulative')
<pstats.Stats object at 0x7f5cca3f0ef0>
>>> p.print_stats()
Sat Nov 28 06:58:28 2015 profile.stats
2000004 function calls in 8.477 seconds
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 8.477 8.477 {built-in method exec}
1 0.000 0.000 8.477 8.477 index.py:1(<module>)
1 4.375 4.375 8.477 8.477 index.py:3(fn)
1000000 2.088 0.000 2.088 0.000 {method 'pop' of 'list' objects}
1000000 2.015 0.000 2.015 0.000 {method 'append' of 'list' objects}
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
<pstats.Stats object at 0x7fadfcc20f28>
その他にも
-
print_callers()-- 呼び出し側の情報 -
print_callees()-- 関数が別の関数を呼び出した時の情報
などを表示できる
line_profiler
- 処理の実行回数と実行時間を行単位で計測するツール
インストール
pip install line_profiler
git clone https://github.com/rkern/line_profiler.git
サンプルコード
profiling
@profile
def fn():
l = []
for _ in range(1000000):
l.append('hoge')
l.pop()
fn()
測定
> python line_profiler/kernprof.py -l -v index.py
Wrote profile results to index.py.lprof
Timer unit: 1e-06 s
Total time: 8.31965 s
File: index.py
Function: fn at line 2
Line # Hits Time Per Hit % Time Line Contents
==============================================================
2 @profile
3 def fn():
4 1 6 6.0 0.0 l = []
5 1000001 2641832 2.6 31.8 for _ in range(1000000):
6 1000000 2806484 2.8 33.7 l.append('hoge')
7 1000000 2871333 2.9 34.5 l.pop()
- His -- 呼び出された回数
- Time -- 実行時間
- Per Hit -- 1回の実行時間
- % Time -- 全体の実行時間に対する1行あたりの実行時間
memory_profiler
- line_profilerのメモリ版
インストール
pip install memory_profile
pip install psutil
サンプルコード
line_profilerと同様
測定
> python -m memory_profiler index.py
Filename: index.py
Line # Mem usage Increment Line Contents
================================================
2 10.316 MiB 0.000 MiB @profile
3 def fn():
4 10.320 MiB 0.004 MiB l = []
5 10.320 MiB 0.000 MiB for _ in range(1000000):
6 10.320 MiB 0.000 MiB l.append('hoge')
7 10.320 MiB 0.000 MiB l.pop()