福岡は今日も雨

情報系大学生のブログ。主に技術,音楽について。

IPythonのまとめ(プロファイリング)

便利な便利なIPythonを使いこなすための自分用まとめ.
今回はプロファイリング関係でまとめました. その他は次.

プロファイリング関係

(1) %timeit

プロファイリングの時に実行するコマンド.
何回か最適な回数を自動的に実行し, 早く実行できたものの平均値を出力してくれる.

In [1]: import numpy as np

In [2]: %timeit a = [x*x for x in np.random.randn(10000)]
1000 loops, best of 3: 1.75 ms per loop

In [3]: %timeit a = np.random.randn(10000); a = a*a
1000 loops, best of 3: 367 µs per loop

Python(特にnumpy絡み)は処理の違いで実行時間が大きく異なる. IPythonはそれを検証するのに便利
スクリプト全体をプロファイリングしたいときは, 全体の実行時間分布をプロファイリングできる

    In [2]: %run -p -s cumulative prun1.py

    61 function calls (60 primitive calls) in 0.062 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      2/1    0.000    0.000    0.062    0.062 {built-in method builtins.exec}
        1    0.000    0.000    0.062    0.062 <string>:1(<module>)
        1    0.000    0.000    0.062    0.062 interactiveshell.py:2443(safe_execfile)
        1    0.000    0.000    0.062    0.062 py3compat.py:181(execfile)
        1    0.001    0.001    0.062    0.062 prun1.py:1(<module>)
        1    0.001    0.001    0.061    0.061 prun1.py:13(func_both)
        2    0.054    0.027    0.054    0.027 {method 'randn' of 'mtrand.RandomState' objects}
        1    0.004    0.004    0.048    0.048 prun1.py:8(func_b)
        1    0.002    0.002    0.012    0.012 prun1.py:3(func_a)
        1    0.000    0.000    0.000    0.000 {built-in method builtins.compile}
        2    0.000    0.000    0.000    0.000 {built-in method io.open}
        1    0.000    0.000    0.000    0.000 posixpath.py:355(abspath)
        1    0.000    0.000    0.000    0.000 {built-in method posix.getcwd}
        1    0.000    0.000    0.000    0.000 posixpath.py:145(dirname)
        1    0.000    0.000    0.000    0.000 posixpath.py:318(normpath)
        1    0.000    0.000    0.000    0.000 syspathcontext.py:64(__exit__)
        1    0.000    0.000    0.000    0.000 {method 'read' of '_io.BufferedReader' objects}
        1    0.000    0.000    0.000    0.000 _bootlocale.py:23(getpreferredencoding)
        1    0.000    0.000    0.000    0.000 posixpath.py:71(join)
        1    0.000    0.000    0.000    0.000 syspathcontext.py:54(__init__)
        1    0.000    0.000    0.000    0.000 syspathcontext.py:57(__enter__)
        1    0.000    0.000    0.000    0.000 codecs.py:308(__init__)
        1    0.000    0.000    0.000    0.000 posixpath.py:221(expanduser)
        3    0.000    0.000    0.000    0.000 posixpath.py:39(_get_sep)
        1    0.000    0.000    0.000    0.000 {built-in method _locale.nl_langinfo}
        1    0.000    0.000    0.000    0.000 {method 'split' of 'str' objects}
        1    0.000    0.000    0.000    0.000 posixpath.py:61(isabs)
        5    0.000    0.000    0.000    0.000 {method 'startswith' of 'str' objects}
  • s cumulativeは積算時間をソートして表示する. あんまり求めてないものも出て見にくいような感じがする.

全体ではなく, 一部の関数のみをプロファイリングしたいときは, %prunというマジックコマンドを利用する.

In [4]: %prun [a, b]=prun1.func_both()
         8 function calls in 0.055 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        2    0.051    0.025    0.051    0.025 {method 'randn' of 'mtrand.RandomState' objects}
        1    0.002    0.002    0.044    0.044 prun1.py:8(func_b)
        1    0.001    0.001    0.055    0.055 prun1.py:13(func_both)
        1    0.000    0.000    0.010    0.010 prun1.py:3(func_a)
        1    0.000    0.000    0.055    0.055 {built-in method builtins.exec}
        1    0.000    0.000    0.055    0.055 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

func_a()に0.010秒, func_bに0.044秒かかっていることが分かる.
このように, prunを利用することで関数レベルで見ることも可能(一応上のにも出てるけど, こちらのほうが絞られていて見やすい)
行レベルでどの式が処理時間をどれくらい必要としているのかを調べるために, line_profilerを使って調べられる. %lprunを使う
ただこのlprunは先に用意が必要で, pip install lineproflierをした後, %load_ext line_profilerを使わなければならない.. 毎回呼び出す必要があるので,
多分configかなんかを触ればその必要が消えるんじゃないかとか思っています.. つかってみると以下

In [6]: %lprun -f func_c func_c()
Timer unit: 1e-06 s

Total time: 0.118285 s
File: /Users/nishimurataichi/today/prun1.py
Function: func_c at line 5

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     5                                           def func_c():
     6         1         1569   1569.0      1.3  	A = np.arange(0, n*n).reshape(n, n) + np.identity(n)
     7         1           21     21.0      0.0  	b = np.arange(0, n)
     8         1       116695 116695.0     98.7  	x = np.dot(np.linalg.inv(A), b)

Timer unitが元となる時間であり, TimeというのがTIme unitの何倍かを表しています. 8行目で116695倍の時間を使っているとわかります. ヒエ〜.
次はメモリのプロファイリングをしていこう

In [9]: %memit a = [x for x in range(1000000)]
peak memory: 148.42 MiB, increment: 62.40 MiB

これだと, 実行文の詳細な行レベルでのメモリ使用量を測定することができない.
それを知りたいときは%mprunマジックコマンドで内訳を見る.

In [11]: mprun -f prun1.func_c prun1.func_c()
Filename: /Users/nishimurataichi/today/prun1.py

Line #    Mem usage    Increment   Line Contents
================================================
     5    127.4 MiB      0.0 MiB   def func_c():
     6    127.4 MiB      0.0 MiB   	A = np.arange(0, n*n).reshape(n, n) + np.identity(n)
     7    127.4 MiB      0.0 MiB   	b = np.arange(0, n)
     8    127.4 MiB      0.0 MiB   	x = np.dot(np.linalg.inv(A), b)


@profileによって, ソースコードに仕込む方法.
ipdb.set_trace()みたいな形で使えるという.

import numpy as np
from memory_profiler import profile

@profile
def func_a():
	a = np.random.randn(500, 500)
	return a**2


@profile
def func_b():
	a = np.random.randn(1000, 1000)
	return a**2


def func_both():
	a = func_a()
	b = func_b()
	return [a, b]


func_both()

結果は以下

In [12]: run prun1
Filename: /Users/nishimurataichi/today/prun1.py

Line #    Mem usage    Increment   Line Contents
================================================
     4    127.4 MiB      0.0 MiB   @profile
     5                             def func_a():
     6    129.4 MiB      1.9 MiB   	a = np.random.randn(500, 500)
     7    131.3 MiB      1.9 MiB   	return a**2


Filename: /Users/nishimurataichi/today/prun1.py

Line #    Mem usage    Increment   Line Contents
================================================
    10    131.0 MiB      0.0 MiB   @profile
    11                             def func_b():
    12    138.6 MiB      7.6 MiB   	a = np.random.randn(1000, 1000)
    13    146.3 MiB      7.6 MiB   	return a**2