Pythonコードのプロファイリング

普段、Pythonのコードは何となく速かろうという、言ってみれば勘で書いているのだけど、その勘とやらは往々にしてウンコードを生むものである。そこで、プロファイラを使っていきたいと思う。

使えそうなツール

そういうわけで、いくつか使えそうなツールをリストアップした。

経過時間のプロファイラ

ツール名 メモ
profile ビルトイン, ピュアPythonの決定論的プロファイラ
cProfile ビルトイン, C拡張の決定論的プロファイラ
line_profiler 行単位の決定論的プロファイラ
Plop 統計的プロファイラ, Dropboxの人が作ってる
statprof 統計的プロファイラ, 開発停止?
yep 拡張モジュール用の統計的プロファイラ, バックエンドにgoogle-perftools

メモリのプロファイラ

ツール名 メモ
memory_profiler 行単位でメモリ消費量の増減を記録
Heapy オブジェクトごとのメモリ消費量を記録
Pympler 同上, 新参プロジェクト

可視化ツール

ツール名 メモ
RunSnakeRun cProfile用の可視化ツール
Gprof2Dot.py cProfileの結果をGraphviz用のDOTファイルに変換
pycallgraph cProfileの結果からGraphvizを用いてコールグラフを作成


物は試しということで、ざっくり使ってみた。
使ってみた感じだと、cProfile, line_profiler, memory_profiler, pymplerあたりが良いかなーという感じがしている。

経過時間のプロファイラ

実験用の適当な関数を用意した。

def fib( n ): 
    a, b = 1, 0 
    fibs = [ a ]
    for i in xrange( n-1 ):
        a, b = a+b, a     
        fibs.append( a )
    return fibs

profile, cProfile

26.4. Python プロファイラ — Python 2.7ja1 documentation

ビルトインの決定論的プロファイラ。プロファイラの拡張を考えていないならオーバーヘッドの少ないcProfileを使う。profileとcProfileのインターフェースはほぼ共通とのこと。プロファイリングの結果は、pstatsモジュールを介して操作する。

cPofileでプロファイルするには、以下のようにrunメソッドに文字列で計測したいコードを渡すだけで良い。

> import cProfile
> cProfile.run( 'fib( 10000 )' ) 
 10002 function calls in 0.013 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.002    0.002    0.013    0.013 <string>:1(<module>)
        1    0.010    0.010    0.011    0.011 pfuncs.py:4(fib)
     9999    0.001    0.000    0.001    0.000 {method 'append' of 'list' objects}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

第二引数にファイル名を指定すればファイルに出力できる。結果の totimeは純粋にその関数の実行に掛かった時間で、cumtimeがその関数の開始から終了までに掛かった時間として出力されるので、たとえば以下のように仕事中に居眠りをしても、

> import time
> def work(): time.sleep( 10 );
> cProfile.run( 'work()' )
         4 function calls in 10.001 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000   10.001   10.001 <ipython-input-7-e692e76a1f37>:1(work)
        1    0.000    0.000   10.001   10.001 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        1   10.001   10.001   10.001   10.001 {time.sleep}

というように、本質的に悪いのは従業員ではないことも分かる。

あるいは以下のような書き方も出来る。

> prf = cProfile.Profile()
> fibs = prf.runcall( fib, 10 )
> fibs
[1, 1, 2, 3, 5, 8, 13, 21, 34, 55]
>
> prf.print_stats() #結果の出力
         11 function calls in 0.000 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 pfuncs.py:4(fib)
        9    0.000    0.000    0.000    0.000 {method 'append' of 'list' objects}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
>
> prf.dump_stats( 'filename' ) #結果をファイルに出力
> prf.clear() #クリアしない場合は、結果が追加されていく。

ファイル全体をプロファイルするには以下のようにする。

% python -m cProfile test.py
         1003 function calls in 0.001 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 pfuncs.py:4(<module>)
        1    0.000    0.000    0.000    0.000 pfuncs.py:4(fib)
        1    0.000    0.000    0.001    0.001 test.py:1(<module>)
      999    0.000    0.000    0.000    0.000 {method 'append' of 'list' objects}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

結果の操作はpstatsを使う。

> import pstats 
> p = pstats.Stats( 'file_name' ) # 結果をファイルに出力した場合はファイル名を指定する
> # あるいは
> p = pstats.Stats( prf ) # Profileインスタンスを渡しても良い
> p.sort_stats( 'time' ).print_stats() #ソートしてみる
         3005 function calls in 3.003 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    3.001    3.001    3.001    3.001 {time.sleep}
        1    0.001    0.001    0.002    0.002 pfuncs.py:4(fib)
     2999    0.000    0.000    0.000    0.000 {method 'append' of 'list' objects}
        2    0.000    0.000    3.003    1.501 <ipython-input-7-5a9078f548de>:1(lazy)
        2    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

ちなみに、IPythonなら%prunマジックでショートカットできる。

> %prun fib( 100 )
         102 function calls in 0.000 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 pfuncs.py:4(fib)
       99    0.000    0.000    0.000    0.000 {method 'append' of 'list' objects}
        1    0.000    0.000    0.000    0.000 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

line_profiler

http://pythonhosted.org/line_profiler/

line_profilerは行単位でプロファイルしてくれる。pipでインストールするとkernprof.pyがコマンドとして使えるようになる。

まず、プロファイル対象の関数に@profileデコレータを付しておく。

# target.py
@profile
def fib( n ): 
    a, b = 1, 0 
    fibs = [ a ]
    for i in xrange( n-1 ):
        a, b = a+b, a     
        fibs.append( a )
    return fibs
if __name__ == '__main__':
    fib( 1000 )

これで、kernprof.pyを実行すると、__builtins__空間にprofileを挿入して、プロファイルを開始する。

% kernprof.py -l target.py
Wrote profile results to target.py.lprof
% python -m line_profiler target.py.lprof
Timer unit: 1e-06 s

File: target.py
Function: fib at line 4
Total time: 0.002766 s

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     4                                           @profile
     5                                           def fib(n):
     6         1            2      2.0      0.1      a, b = 1, 0
     7         1            1      1.0      0.0      fibs = [a]
     8      1000          837      0.8     30.3      for i in xrange(n-1):
     9       999          966      1.0     34.9          a, b = a+b, a
    10       999          959      1.0     34.7          fibs.append(a)
    11         1            1      1.0      0.0      return fibs

あるいは、cProfileと同様にインスタンスを取得して操作することも出来る。APIは親切にもcProfileとほとんど同じ。

> from line_profiler import LineProfiler
> prf = LineProfiler() #インスタンスに複数の関数を与えても良い。
> prf.add_function( fib )
> prf.runcall( fib, 100 )
> prf.print_stats()
Timer unit: 1e-06 s

File: pfuncs.py
Function: fib at line 4
Total time: 0.000289 s

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     4                                           def fib(n): 
     5         1            2      2.0      0.7      a, b = 1, 0 
     6         1            1      1.0      0.3      fibs = [a]
     7       100           85      0.8     29.4      for i in xrange(n-1):
     8        99           95      1.0     32.9          a, b = a+b, a     
     9        99          105      1.1     36.3          fibs.append(a)
    10         1            1      1.0      0.3      return fibs
>
> prf.dump_stats( 'fib.lprof' ) # fib.lprofへ結果を出力

IPythonを使うときは、以下の設定をする。

#~/.ipython/profile_default/ipython_config.py
c = get_config()
c.TerminalIPythonApp.extensions = [ 'line_profiler' ] #ターミナル用
c.InteractiveShellApp.extensions = [ 'line_profiler' ] #QtConsole用

これで、%lprunマジックが使えるようになる。

> from myfuncs import fib
> %lprun -f fib fib( 300 )
%lprun -f fib fib( 100 )

Timer unit: 1e-06 s

File: pfuncs.py
Function: fib at line 4
Total time: 0.000284 s

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     4                                           def fib(n): 
     5         1            2      2.0      0.7      a, b = 1, 0 
     6         1            1      1.0      0.4      fibs = [a]
     7       100           82      0.8     28.9      for i in xrange(n-1):
     8        99           97      1.0     34.2          a, b = a+b, a     
     9        99          101      1.0     35.6          fibs.append(a)
    10         1            1      1.0      0.4      return fibs

どうもその場で定義した関数をプロファイルするのは出来ないらしい。

Plop

https://github.com/bdarnell/plop

Plopは統計的プロファイラで、Dropboxのワークショップとやらで開発が始まったらしい。プロファイル結果は、D3というJavascriptの可視化ライブラリを介して確認する。

部分的にサンプリングしたいときは、以下のようにCollector.startとstopで囲む。

from pfuncs import fib
from threading import Thread
import time, random as rnd

def boss( n ):
    workers = []
    for i in range(n):
       wrkr = Thread( target=worker, args=( rnd.randint(5, 10) ,) ) 
       wrkr.start()

def worker( t ):
    time.sleep( t )
    f = fib( 10000*t )
    print "I have calculated %d " % len( f )

if __name__ == '__main__':
    from plop import collector
    c = collector.Collector() 
    c.start() 
    boss( 3 )
    c.stop()

あるいは、全体を対象にするには以下のようにする。

python -m plop.collector test.py

結果は付属のtornado製のツールで確認する。結果ファイルはデフォルトだと/tmpに入る。

% python -m plop.viewer --datadir=/tmp #これでサーバが起動するので、localhost:8888へ。

一覧の中からファイル(plop.out)を選択すると、こんな感じのグラフが出現する。
http://farm6.staticflickr.com/5549/9488307145_8d88a53ebe_z.jpg
ノードの色は、ファイルごとに分けられる。ノードの大きさは、消費時間を表している。リンクの太さが、呼び出し回数に比例するようになっている。

Webアプリケーション向けですね。

statprof

https://pypi.python.org/pypi/statprof/

これも統計的プロファイラ。

# file: test.py
import time
from pfuncs import fib

def lazy(t):
    time.sleep( t )
    return fib( 1000*t )
    
import statprof
statprof.start()
for i in range( 1, 10 ):
    lazy( i )
statprof.stop()
statprof.display()

このコードを実行すると、以下のような出力が得られる。

% python test.py
  %   cumulative      self
 time    seconds   seconds  name
 80.00      0.02      0.02  pfuncs.py:8:fib
 20.00      0.02      0.00  test.py:11:<module>
  0.00      0.02      0.00  test.py:6:lazy
---
Sample count: 20
Total time: 0.020000 seconds

yep

https://pypi.python.org/pypi/yep

C/C++/Fortran拡張モジュールのための統計的プロファイラ。yepはgperftoolsを使って拡張モジュールをプロファイリングする。

正直、開発中にCのプロファイラを忍ばせておけば良いので、どういうときに使うのか分からない。とはいえ、見つけてしまったので、試してみた。

ここでフィボナッチアゲイン。

/* file: cfuncs.c */
#include "Python.h"
#include <gmp.h>

static PyObject *err;

static PyObject *fib( PyObject* self, PyObject* args ) {
    int n;
    PyObject *res;
    res = PyList_New( 0 ); 
    
    if ( !PyArg_ParseTuple( args, "i", &n ) ) {
        return NULL;
    }

    if ( n <= 0 ){
        PyErr_SetString( err, "Argument must be grater than zero." );
        return NULL;
    } else if ( n == 1 ) {
        PyList_Append( res, Py_BuildValue( "i", 1 ) );
        return res;
    }
    
    char *f = NULL;
    mpz_t a, b, c;
    mpz_init( a ); mpz_init( b ); mpz_init( c );
    mpz_set_ui( a, 1 ); mpz_set_ui( b, 0 );
    
    PyList_Append( res, PyLong_FromString( mpz_get_str( f, 10, a ), NULL, 10 ) );
    int i;
    for ( i=0; i<n-1; i++ ) {
        mpz_set( c, a );
        mpz_add( a, b, c );
        mpz_set( b, c );
        PyList_Append( res,  PyLong_FromString( mpz_get_str( f, 10, a ), NULL, 10 ) );
    }

    return res;
}

static PyMethodDef methods[] ={ 
    { "fib", fib, METH_VARARGS, "fibonacci sequence: fib(num)" }, 
    { NULL, NULL, 0, NULL }  
};

PyMODINIT_FUNC initcfuncs( void ) {
    ( void ) Py_InitModule( "cfuncs", methods );
}

ビルド用のスクリプトは以下

# file: setup.py
from distutils.core import setup, Extension
cfuncs = Extension( 'cfuncs', sources=[ 'cfuncs.c' ], libraries=[ 'gmp' ] )
setup( name='cFuncs', version='0.1', description='C Extensions', ext_modules=[ cfuncs ] )

この洗練された拡張モジュールは、見ての通りgmpの関数をやたらと呼び出している。手っ取り早くオーバーフローを防ごうとしたらこのザマである。
(実は、この拡張モジュールはピュアPythonよりも遅い!)

実行は、以下のようにする。

> import yep
> from cfuncs import fib #上で作った拡張モジュール
>
> yep.start( 'fib.prof' ) # 結果が fib.prof に出力される
> fibs = fib( 30000 )
> yep.stop()

プロファイル結果をpprofコマンドに渡せば、インタラクティブシェルが起動する

% pprof /bin/ls fib.prof

Using local file /bin/ls.
Using local file fib.prof.
Removing __sigtramp from all stack traces.
Welcome to pprof!  For help, type 'help'.
(pprof) top #上位10件を表示
Total: 564 samples
     400  70.9%  70.9%      400  70.9% ___gmp_tmp_reentrant_alloc
      27   4.8%  75.7%       27   4.8% _malloc_jumpstart
      21   3.7%  79.4%       21   3.7% ___gmpn_copyi
      19   3.4%  82.8%       30   5.3% ___gmpn_get_str
      17   3.0%  85.8%       17   3.0% 0x000000010562ca31
      16   2.8%  88.7%       16   2.8% 0x000000010562ca10
      12   2.1%  90.8%       12   2.1% ___gmpn_tdiv_qr
      11   2.0%  92.7%       11   2.0% 0x000000010562ca1b
       9   1.6%  94.3%        9   1.6% 0x000000010562c960
       7   1.2%  95.6%        7   1.2% 0x000000010562ca21
(pprof)
(pprof) web #svgファイルにコールグラフを出力
Total: 564 samples
Dropping nodes with <= 2 samples; edges with <= 0 abs(samples)
Loading web page file:////tmp/pprof34359.0.svg

出力されたコールグラフはこんな感じ
http://farm6.staticflickr.com/5336/9483959959_9dc00a7877_z.jpg

あるいは、標準出力に表示するには以下のようにする。

% python -m yep -v test.py
Using local file /usr/local/Cellar/python/2.7.3/Frameworks/Python.framework/Versions/2.7/Resources/Python.app/Contents/MacOS/Python.
Using local file test.py.prof.
Removing __sigtramp from all stack traces.
Total: 564 samples
       0   0.0%   0.0%      501  88.8% __mh_execute_header
     380  67.4%  67.4%      380  67.4% ___gmp_tmp_reentrant_alloc
       0   0.0%  67.4%      125  22.2% __tlv_bootstrap
      26   4.6%  72.0%       48   8.5% ___gmpn_get_str
      24   4.3%  76.2%       24   4.3% _malloc_jumpstart
      23   4.1%  80.3%       23   4.1% ___gmpn_copyi
      19   3.4%  87.4%       19   3.4% ___gmpn_tdiv_qr
       0   0.0%  87.4%       19   3.4% _create_scalable_zone
       0   0.0%  87.4%       18   3.2% ___gmp_tmp_reentrant_free
       0   0.0%  87.4%       18   3.2% _free
       0   0.0%  97.3%        4   0.7% ___gmp_default_allocate
       0   0.0%  97.3%        4   0.7% _malloc
       0   0.0%  97.3%        4   0.7% _malloc_zone_malloc
       3   0.5%  97.9%        3   0.5% ___gmpn_sqr_basecase
       0   0.0%  97.9%        3   0.5% __sigtramp
       1   0.2%  98.4%        2   0.4% ___gmpn_sbpi1_div_qr
       2   0.4%  98.8%        2   0.4% ___gmpz_get_str
       0   0.0%  99.8%        1   0.2% ProfileHandler::once_
       0   0.0%  99.8%        1   0.2% ___gmpn_dcpi1_div_qr
       1   0.2% 100.0%        1   0.2% ___gmpn_sub_n
       0   0.0% 100.0%        1   0.2% _realloc

なるほどそういう感じね;;


メモリのプロファイラ

メモリのプロファイラには、行単位でスナップショットを撮るものと、指定された時間にオブジェクトごとのスナップショットを撮るものがある。

memory_profiler

https://github.com/fabianp/memory_profiler

Pythonインタプリタのプロセスのメモリ消費を監視してて、行単位でその差分を記録してくれる。裏でpsutilモジュールを使う。

画像を読めばメモリ食うだろうということで、試しに画像のガンマ補正をしてみる。

# file: test.py
from PIL import Image

@profile
def gamma( name, gam ):
    img = Image.open( name )
    pix = img.load()
    for i in xrange( img.size[ 0 ] ):
        for j in xrange( img.size[ 1 ] ):
            pix[ i, j ] = tuple( [ int( 255.*( c/255. )**( 1./gam ) ) for c in pix[ i, j ] ] )
    img.save( name+'_after.jpg' )

if __name__ == '__main__':
    gamma( 'large.jpg', 1.6 )

結果は以下のとおり。

% python -m memory_profiler test.py
Filename: test.py

Line #    Mem usage    Increment   Line Contents
================================================
     4                             @profile
     5     9.473 MB     0.000 MB   def gamma( name, gam ):
     6     9.691 MB     0.219 MB       img = Image.open( name )
     7    66.668 MB    56.977 MB       pix = img.load()
     8    67.332 MB     0.664 MB       for i in xrange( img.size[0] ):
     9   525.109 MB   457.777 MB           for j in xrange( img.size[1] ):
    10  2232.520 MB  1707.410 MB               pix[ i, j ] = tuple( [ int(255.*(c/255.)**(1./gam)) for c in pix[i, j] ] )
    11  2232.637 MB     0.117 MB       img.save( name+"_after.jpg" )

画像処理すごい。

あるいは時間間隔で計測することも出来る。

> from memory_profiler import memory_usage
> from pfuncs import fib
> import time
>
> def lazy( t ): time.sleep( t ); fibs = fib( 10000*t ); time.sleep( t )
>
> mu = memory_usage( ( lazy, ( 3, ) ), interval=.01, timeout=20 )
> mu
(略)
 44.04296875,
 44.04296875,
 44.04296875,
 44.04296875,
 44.04296875,
 46.66796875,
 53.83203125,
 62.9453125,
 71.78125,
 80.2421875,
 89.796875,
 89.796875,
 89.796875,
 89.796875,
 89.796875,
 89.796875,
 89.796875,
 89.796875,
 89.796875,
(略)

IPythonで使うときは、例によって設定ファイルに以下を追加する。

# file: ~/.ipython/profile_default/ipython_config.py
c = get_config()
c.TerminalIPythonApp.extensions = [ 'memory_profiler' ]
c.InteractiveShellApp.extensions = [ 'memory_profiler' ]

これで%mprunマジックが使えるようになる。

> from pfuncs import lazy
> %mprun -f lazy lazy( 3 )
Filename: pfuncs.py

Line #    Mem usage    Increment   Line Contents
================================================
     4    44.277 MB     0.000 MB   def lazy(t):
     5    44.277 MB     0.000 MB       import time
     6    44.277 MB     0.000 MB       time.sleep(t)
     7    89.824 MB    45.547 MB       fibs = fib(10000*t)
     8    89.824 MB     0.000 MB       time.sleep(t)
     9    89.824 MB     0.000 MB       return fibs

これもファイルからインポートした関数しか渡せない。

Heapy

http://guppy-pe.sourceforge.net/#Heapy

これが一番有名なのだろうか。Heapyはスナップショットを撮ってオブジェクト毎のメモリ消費量を記録してくれる。

# file: hp.py
from guppy import hpy
hp = hpy()
hp.setrelheap() #参照点, 以後、これ以前のデータセットを差し引く。
print hp.heap(), '\n'
d = { i: range( i ) for i in range( 1000 ) } #意味不明な事をしてみる
print hp.heap()

これを実行すると、以下のような結果が得られる。

% python hp.py
Partition of a set of 1 object. Total size = 448 bytes.
 Index  Count   %     Size   % Cumulative  % Kind (class / dict of class)
     0      1 100      448 100       448 100 types.FrameType

Partition of a set of 277788 objects. Total size = 10984200 bytes.
 Index  Count   %     Size   % Cumulative  % Kind (class / dict of class)
     0 275790  99  6618960  60   6618960  60 int
     1   1000   0  4274432  39  10893392  99 list
     2      4   0    50272   0  10943664 100 dict (no owner)
     3    991   0    39664   0  10983328 100 str
     4      1   0      520   0  10983848 100 types.FrameType
     5      1   0      280   0  10984128 100 dict of guppy.etc.Glue.Owner
     6      1   0       72   0  10984200 100 guppy.etc.Glue.Owner

出力の書式は、いろいろ指定できる。

> h.bytype #オブジェクトタイプごとに
Partition of a set of 277788 objects. Total size = 10984200 bytes.
 Index  Count   %     Size   % Cumulative  % Type
     0 275790  99  6618960  60   6618960  60 int
     1   1000   0  4274432  39  10893392  99 list
     2      5   0    50552   0  10943944 100 dict
     3    991   0    39664   0  10983608 100 str
     4      1   0      520   0  10984128 100 types.FrameType
     5      1   0       72   0  10984200 100 types.InstanceType
>
> h.byrcs #オブジェクトの参照を辿ってリファラごとに
Partition of a set of 277788 objects. Total size = 10984200 bytes.
 Index  Count   %     Size   % Cumulative  % Kind (class / dict of class)
     0 275790  99  6618960  60   6618960  60 int
     1   1000   0  4274432  39  10893392  99 list
     2      4   0    50272   0  10943664 100 dict (no owner)
     3    991   0    39664   0  10983328 100 str
     4      1   0      520   0  10983848 100 types.FrameType
     5      1   0      280   0  10984128 100 dict of guppy.etc.Glue.Owner
     6      1   0       72   0  10984200 100 guppy.etc.Glue.Owner
> 
> h.byid #オブジェクトのID毎に
Set of 277788 <mixed> objects. Total size = 10984200 bytes.
 Index     Size   %   Cumulative  %   Brief
     0    49432   0.5     49432   0.5 dict (no owner): 0x7fc552626f10*1000
     1     8264   0.1     57696   0.5 list: 0x10afa1908*960
     2     8264   0.1     65960   0.6 list: 0x10afa1950*961
     3     8264   0.1     74224   0.7 list: 0x10afa1998*962
     4     8264   0.1     82488   0.8 list: 0x10afa19e0*963
     5     8264   0.1     90752   0.8 list: 0x10afa1a28*964
     6     8264   0.1     99016   0.9 list: 0x10afa1a70*965
     7     8264   0.1    107280   1.0 list: 0x10afa1ab8*966
     8     8264   0.1    115544   1.1 list: 0x10afa1b00*967
     9     8264   0.1    123808   1.1 list: 0x10afa1b48*968
<277778 more rows. Type e.g. '_.more' to view.> # '_'はインタプリタで直前に評価した値
> 
> h.byvia #参照属性ごとに
Partition of a set of 277788 objects. Total size = 10984200 bytes.
 Index  Count   %     Size   % Cumulative  % Referred Via:
     0      1   0    49432   0     49432   0 "['d']"
     1    742   0    17808   0     67240   1 '[257]'
     2    741   0    17784   0     85024   1 '[258]'
     3    740   0    17760   0    102784   1 '[259]'
     4    739   0    17736   0    120520   1 '[260]'
     5    738   0    17712   0    138232   1 '[261]'
     6    737   0    17688   0    155920   1 '[262]'
     7    736   0    17664   0    173584   2 '[263]'
     8    735   0    17640   0    191224   2 '[264]'
     9    734   0    17616   0    208840   2 '[265]'
<2867 more rows. Type e.g. '_.more' to view.>
>
> h.bysize 
Partition of a set of 277788 objects. Total size = 10984200 bytes.
 Index  Count   %     Size   % Cumulative  % Individual Size
     0 275790  99  6618960  60   6618960  60        24
     1     64   0   496128   5   7115088  65      7752
     2     64   0   463360   4   7578448  69      7240
     3     64   0   430592   4   8009040  73      6728
     4     64   0   397824   4   8406864  77      6216
     5     64   0   365056   3   8771920  80      5704
     6     64   0   332288   3   9104208  83      5192
     7     40   0   330560   3   9434768  86      8264
     8     64   0   299520   3   9734288  89      4680
     9     64   0   266752   2  10001040  91      4168
<40 more rows. Type e.g. '_.more' to view.>

さらに、個別要素の参照をたどるとかいうことも出来る。

> h.byid[ 3 ].byrcs
Partition of a set of 1 object. Total size = 8264 bytes.
 Index  Count   %     Size   % Cumulative  % Referrers by Kind (class / dict of class)
     0      1 100     8264 100      8264 100 dict (no owner)

正直まだよく分かっていない。

Pympler

https://github.com/pympler/pympler

概ねHeapyと同じようなもので、オブジェクトごとのメモリ消費量を知らせてくれる。

たとえばオブジェクトのサイズを得るにはasizeofを使う。

> from pympler.asizeof import asizeof
> asizeof( 10 ) #バイトサイズが返ってくる
24
> asizeof( range( 10 ) )
392
>
> class Spam:
     def __init__( self ):
         self.n = "spammer"
     def wisper( self ):
         print "I am a spammer."
>
> asizeof( Spam() )
440

存在するオブジェクトを取得したり、サマリーしたりするにはmuppyやsummaryを使う。

> from pympler import muppy
> muppy.print_summary()
                       types |   # objects |   total size
============================ | =========== | ============
                        dict |         504 |    785.44 KB
                         str |        5289 |    489.42 KB
                        code |        1339 |    167.38 KB
                        list |         229 |    142.55 KB
          wrapper_descriptor |        1020 |     79.69 KB
                        type |          81 |     71.51 KB
  builtin_function_or_method |         693 |     48.73 KB
           method_descriptor |         408 |     28.69 KB
                         set |         108 |     27.97 KB
                     weakref |         316 |     27.16 KB
                       tuple |         260 |     19.18 KB
           member_descriptor |         225 |     15.82 KB
         <class abc.ABCMeta |          16 |     14.12 KB
           getset_descriptor |         141 |      9.91 KB
         function (__init__) |          76 |      8.91 KB
>
> from pympler import summary
> obj1 = muppy.get_objects()
> sum1 = summary.summarize( obj1 )
> summary.print_( sum1 ) #上と同じ結果が得られる
                       types |   # objects |   total size
============================ | =========== | ============
                        dict |         502 |    787.14 KB
                         str |        5288 |    488.96 KB
                        code |        1339 |    167.38 KB
          wrapper_descriptor |        1012 |     79.06 KB
                        type |          81 |     71.51 KB
  builtin_function_or_method |         693 |     48.73 KB
                        list |         228 |     34.22 KB
           method_descriptor |         408 |     28.69 KB
                         set |         108 |     27.97 KB
                     weakref |         313 |     26.90 KB
                       tuple |         266 |     19.84 KB
           member_descriptor |         223 |     15.68 KB
         <class abc.ABCMeta |          16 |     14.12 KB
           getset_descriptor |         139 |      9.77 KB
         function (__init__) |          76 |      8.91 KB
>
> # ~~~適当な処理~~~
>
> obj2 = muppy.get_objects()
> sum2 = summary.summarize( obj2 )
> 
> diff = summary.get_diff( sum1, sum2 ) #差分を取得する
> summary.print_( diff )
                  types |   # objects |   total size
======================= | =========== | ============
                   list |           2 |    109.26 KB
     wrapper_descriptor |           8 |    640     B
                    str |           2 |    503     B
                weakref |           3 |    264     B
      member_descriptor |           2 |    144     B
      getset_descriptor |           2 |    144     B
        module(pympler) |           0 |      0     B
        function (read) |           0 |      0     B
                   code |           0 |      0     B
   function (_subtract) |           0 |      0     B
    function (__whseed) |           0 |      0     B
  function (removedirs) |           0 |      0     B
   function (b64decode) |           0 |      0     B
  function (splitvalue) |           0 |      0     B
     function (pending) |           0 |      0     B
>

このような、差分を追跡する処理には、専用のモジュールがあって以下のようにも書ける。

> from pympler import tracker
> trckr = tracker.SummrayTracker()
>
> trckr.print_diff()
                  types |   # objects |    total size
======================= | =========== | =============
                   list |        1002 |     102.67 KB
                    str |        1006 |      56.75 KB
                    int |         120 |       2.81 KB
     wrapper_descriptor |           8 |     640     B
                weakref |           3 |     264     B
      member_descriptor |           2 |     144     B
      getset_descriptor |           2 |     144     B
                   code |           1 |     128     B
  function (store_info) |           1 |     120     B
                   cell |           2 |     112     B
                  tuple |           0 |       8     B
         instancemethod |          -1 |     -80     B
       _sre.SRE_Pattern |          -8 |    -704     B
                   dict |           2 |   -1744     B
>
> # ~~ 何かしらの処理
> trkcr.print_diff()
  types |   # objects |   total size
======= | =========== | ============
   list |           2 |    968     B
    int |           8 |    192     B
    str |           2 |     97     B
>
> # ~~~さらに何かしらの処理 ~~~
> trckr.print_diff()
  types |   # objects |   total size
======= | =========== | ============
   list |           1 |    872     B
>

それから、特定のクラスのインスタンスを追跡する謎モジュールがあって、これが意外に便利っぽい。

# -*- coding: utf-8 -*-

class Cage:
    def __init__( self, no ):
        self.no = no
        self.pandas = []
    def addPanda( self, panda ):
        self.pandas.append( panda )

class Panda:
    def __init__( self, name, age ):
        self.name = name
        self.age = age

from pympler.classtracker import ClassTracker
trckr = ClassTracker()
trckr.track_class( Cage )
trckr.track_class( Panda )
trckr.create_snapshot()

cage = Cage( 100 )
trckr.create_snapshot()

for i in range( 100 ):
   cage.addPanda( Panda( "ぱんだ"+str( i )+"号", i ) )
trckr.create_snapshot()

trckr.stats.print_summary()

こんな感じでパンダをケージにぶち込んでいく様子は以下のように観察できる。

---- SUMMARY ------------------------------------------------------------------
                                         active      0     B      average   pct
  __main__.Cage                               0      0     B      0     B    0%
  __main__.Panda                              0      0     B      0     B    0%
                                         active      0     B      average   pct
  __main__.Cage                               1    536     B    536     B    0%
  __main__.Panda                              0      0     B      0     B    0%
                                         active      0     B      average   pct
  __main__.Cage                               1      1.35 KB      1.35 KB    0%
  __main__.Panda                            100     42.27 KB    432     B    0%
-------------------------------------------------------------------------------

特定のパンダの様子を観察したければ、以下のようにすれば良い。

my_panda = Panda( "将校", 10 )
trckr.track_object( my_panda )


可視化ツール

そろそろ飽きてきたので、簡単に可視化ツールを見て終わりにする。

RunSnakeRun

http://www.vrplumber.com/programming/runsnakerun/

これはcProfileおよびProfileの結果をグラフィカルに表示するためのツール。インストールは若干面倒だけど頑張って入れる。

実行は、runsnakeコマンドにプロファイラの出力ファイルを渡すだけ。

% runsnake test.prf

こんな感じのが起動する。
http://farm4.staticflickr.com/3763/9515936335_e89958b984_z.jpg

Gprof2Dot.py

https://code.google.com/p/jrfonseca/wiki/Gprof2Dot#python_cProfile_(formerly_known_as_lsprof)

profile, cProfileの出力をGraphvizを使って可視化してくれる。

以下のコマンドで、プロファイラの出力ファイルを渡して画像を生成する。

%  gprof2dot -f pstats test.prf |dot -Tjpg -o test.jpg

こんなのが出来る。
http://farm6.staticflickr.com/5457/9518622228_f36e6cdef4_o.jpg
なるほど、cProfileの出力に相違ない。

PyCallGraph

http://pycallgraph.slowchop.com/

Graphvizを使って、コールグラフを出力してくれる。

描画対象のコードを、pycallgraph.strt_traceとpycallgraph.make_dot_graphで囲むだけ。

> import pycallgraph
> pycallgraph.start_trace()
> # ~~~ 何らかの処理 ~~~
> pycallgraph.make_dot_graph('test.png')

ガンマ補正するコードで試してみたのが以下
http://farm4.staticflickr.com/3729/9515763165_91c6d985f5_c.jpg


メモ

プロファイリングには方法論的に以下の2種類がある。

  • 決定論的プロファイリング
  • 統計的プロファイリング

決定論的プロファイリングは、関数の呼び出しなどのイベントにフックして経過時間を計測する方法で、統計的プロファイリングはプロフラムの何処を実行しているかをランダムにサンプリングして推定する方法である。そのため、決定論的プロファイリングは正確さがウリで、統計的プロファイリングはオーバーヘッドの小ささがウリである。Webアプリケーションなどで、動作中にプロファイリングをしたい場合は、統計的プロファイリングが良いらしい。

それから、プロファイリングの粒度によって、以下の2種類がある。

  • マクロ・プロファイリング
  • マイクロ・プロファイリング

マクロ・プロファイリングとは、モジュールとか関数、ブロックのような、まとまり毎に経過時間を計測するやり方。一方の、マイクロ・プロファイリングは、関数の特定の範囲とか、プログラムの行レベルで経過時間を計測するやり方である。なので、最初にマクロ・プロファイリングをして的を絞ってからマイクロ・プロファイリング、というように徐々に粒度を小さくしていくのが良いらしい。


おわり。