Edited at
PythonDay 7

Pythonプロファイリング基礎

More than 1 year has passed since last update.


プロファイリングとは


  • 必要十分なスピードと無駄のないリソース使用量でコードを実行するためにボトルネックになっている処理を特定すること

  • 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()