Help us understand the problem. What is going on with this article?

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()
Why not register and get more from Qiita?
  1. We will deliver articles that match you
    By following users and tags, you can catch up information on technical fields that you are interested in as a whole
  2. you can read useful information later efficiently
    By "stocking" the articles you like, you can search right away
Comments
Sign up for free and join this conversation.
If you already have a Qiita account
Why do not you register as a user and use Qiita more conveniently?
You need to log in to use this function. Qiita can be used more conveniently after logging in.
You seem to be reading articles frequently this month. Qiita can be used more conveniently after logging in.
  1. We will deliver articles that match you
    By following users and tags, you can catch up information on technical fields that you are interested in as a whole
  2. you can read useful information later efficiently
    By "stocking" the articles you like, you can search right away