Pythonプロファイリング基礎

# プロファイリングとは
- 必要十分なスピードと無駄のないリソース使用量でコードを実行するためにボトルネックになっている処理を特定すること
- python用の有名なツール
  - Pythonとtimeit
  - cProfile
  - line_profiler
  - memory_profiler


# ツールの紹介

## IPythonとtimeit
- python対話型インタンプリタの拡張版
- timeitモジュールでテスト回数（-r）、ループ回数（-n）を指定して平均実行時間を計測
- 短いコードを直接実行とコードファイルをインポートして実行の2パターンがある

### インストール
```py3
pip install ipython
```

### サンプルコード

```py3:profiling.py
def fn_arr():
  for i in range(1000): arr.append(i)
def fn_ls():
  for i in range(1000): ls.append(i)
```

### 測定

シングルコードの実行

```py3: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
```

ファイルを実行

```bash: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
- 標準のプロファイリングツール
- 実行する全ての関数の実行時間を測定

### サンプルコード

```py3:profiling.py
def fn():
  l = []
  for _ in range(1000000):
    l.append('hoge')
    l.pop()
fn()
```

### 測定

ファイルを指定して実行

```bash
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}
```

測定結果を出力

```bash
python -m cProfile -o profile.stats index.py
```

測定結果ファイルを読み込んで表示

```bash
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
- 処理の実行回数と実行時間を行単位で計測するツール

### インストール
```bash
pip install line_profiler
git clone https://github.com/rkern/line_profiler.git
```

### サンプルコード

```py3:profiling
@profile
def fn():
  l = []
  for _ in range(1000000):
    l.append('hoge')
    l.pop()
fn()
```

### 測定

```bash
> 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のメモリ版

### インストール

```bash
pip install memory_profile
pip install psutil
```

### サンプルコード
line_profilerと同様

### 測定

```bash
> 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()
```