あなたが書いたすべてのPythonプログラムで厳密なパフォーマンス計測が必要になるというわけではないにせよ、その時が来たら、役に立ってくれる様々な種類のツールがPythonのエコシステムにはあるのだということを知っておけば安心できるだろう。
プログラムのパフォーマンスを計測することは、すなわち以下の4つの基本的な質問に答えることだと要約できる。
- どのくらい高速に実行できるか？
- スピードのボトルネックはどこか？
- どのくらいのメモリを使うか？
- メモリリークしているのはどこか？
これから、いくつかの素晴らしいツールを使ってこれらの質問に答えていくための詳細を見ていこう。
大ざっぱな実行時間
素早くざっくりとコードの実行時間を計るのに、古き良きUNIXのユーティリティである time を使うところから始めてみよう。
$ time python yourprogram.py
real 0m1.028s
user 0m0.001s
sys 0m0.003s
出力された3つの測定値の意味については、StackOverflowの記事に詳しく書かれているが、簡単に言うと以下のようになっている。
- real 実際にかかった時間
- user カーネルの外の処理でかかった時間
- sys カーネル内の特定の処理でかかった時間
sysとuserの時間を足し合わせれば、同じシステムで動いている他のプログラムと関係なく、自分のプログラムがどのくらいのCPUサイクルを使ったのかが読み取れるはずだ。
sysとuserの合計がrealよりもかなり少ない場合、プログラムのパフォーマンスの問題は、IO待ちにある可能性が高いと考えられる。
コンテキストマネージャを使った詳細な実行時間の取得
次のテクニックでは、より詳細な実行時間の情報を取得するために、直接コードを埋め込む方法を取ってみる。以下のスニペットは、各処理の時間を逐一取得するのにとても有用だ。
timer.py
import time
class Timer(object):
def __init__(self, verbose=False):
self.verbose = verbose
def __enter__(self):
self.start = time.time()
return self
def __exit__(self, *args):
self.end = time.time()
self.secs = self.end - self.start
self.msecs = self.secs * 1000 # millisecs
if self.verbose:
print 'elapsed time: %f ms' % self.msecs
これを使うには、実行時間を計測したいコードのブロックをPythonのwithキーワードを使ってTimerコンテキストマネージャで囲えばよい。コードブロックが実行開始する時にタイマを起動し、コードブロックの実行が終わる時にタイマを停止してくれる。
スニペットの使い方の例がこれだ。
from timer import Timer
from redis import Redis
rdb = Redis()
with Timer() as t:
rdb.lpush("foo", "bar")
print "=> elasped lpush: %s s" % t.secs
with Timer as t:
rdb.lpop("foo")
print "=> elasped lpop: %s s" % t.secs
私はよく、プログラムのパフォーマンスがどう推移していくかを見るために、タイマの出力をファイルに保存している。
プロファイラによる行単位の実行時間と実行頻度の計測
コードの各行がどのくらいの速さでどのくらい実行されているかを見るための、line_profilerという素晴らしいプロジェクトをRobert Kern氏が率いており、私のスクリプトではこれを動かしている。
これを使うには、pipでこのPythonパッケージをインストールする必要がある。
$ pip install line_profiler
インストールすると、line_profilerと呼ばれるモジュールだけでなくkernprof.pyという実行スクリプトにもアクセスできるようになる。
このツールを使うには、計測したい関数を@profileデコレータで修飾するようにソースを修正するところから始める。心配するな。このデコレータを使うために何もインポートする必要はない。kernprof.pyスクリプトは、実行中にスクリプトのランタイムにデコレータを読み込んでくれる。
primes.py
@profile
def primes(n):
if n==2:
return [2]
elif n<2:
return []
s=range(3,n+1,2)
mroot = n ** 0.5
half=(n+1)/2-1
i=0
m=3
while m <= mroot:
if s[i]:
j=(m*m-3)/2
s[j]=0
while j<half:
s[j]=0
j+=m
i=i+1
m=2*i+3
return [2]+[x for x in s if x]
primes(100)
@profileデコレータを使ってコードを準備したら、スクリプトをkernprof.pyを使って実行しよう。
$ kernprof.py -l -v fib.py
-lオプションはkernprofに対し、@profileデコレータをスクリプトのビルトインに読み込むように指示するもので、-vはスクリプト終了時に実行時間情報を表示するという意味だ。上のスクリプトの実行結果は以下のようになる。
Wrote profile results to primes.py.lprof
Timer unit: 1e-06 s
File: primes.py
Function: primes at line 2
Total time: 0.00019 s
Line # Hits Time Per Hit % Time Line Contents
==============================================================
2 @profile
3 def primes(n):
4 1 2 2.0 1.1 if n==2:
5 return [2]
6 1 1 1.0 0.5 elif n<2:
7 return []
8 1 4 4.0 2.1 s=range(3,n+1,2)
9 1 10 10.0 5.3 mroot = n ** 0.5
10 1 2 2.0 1.1 half=(n+1)/2-1
11 1 1 1.0 0.5 i=0
12 1 1 1.0 0.5 m=3
13 5 7 1.4 3.7 while m <= mroot:
14 4 4 1.0 2.1 if s[i]:
15 3 4 1.3 2.1 j=(m*m-3)/2
16 3 4 1.3 2.1 s[j]=0
17 31 31 1.0 16.3 while j<half:
18 28 28 1.0 14.7 s[j]=0
19 28 29 1.0 15.3 j+=m
20 4 4 1.0 2.1 i=i+1
21 4 4 1.0 2.1 m=2*i+3
22 50 54 1.1 28.4 return [2]+[x for x in s if x]
ヒット数が多かったり、時間が長い行を見てみよう。それが、最適化が大きな性能改善を見せるであろう部分だ。
どのくらいのメモリを使っているか？
これで自分のコードの実行時間をうまく知ることができるようになった。次は、プログラムがどのくらいのメモリを使っているのかを解き明かしにかかろう。幸いなことに、Robert Kern氏のline_profilerを参考にFabian Pedregosa氏が作ったmemory_profilerというものがある。
まずはpipでインストールしよう。
$ pip install -U memory_profiler
$ pip install psutil
(memory_profilerのパフォーマンスを劇的によくするので、psutilパッケージもインストールすることをおすすめする)
line_profilerと同じように、memory_profilerを使う際には、計測したい関数を@profileデコレータで修飾する必要がある。
@profile
def primes(n):
...
...
関数がどのくらいのメモリを使っているか見るには以下のようにする。
$ python -m memory_profiler primes.py
プログラムが終了すると、以下のような実行結果が表示されるはずだ。
Filename: primes.py
Line # Mem usage Increment Line Contents
==============================================
2 @profile
3 7.9219 MB 0.0000 MB def primes(n):
4 7.9219 MB 0.0000 MB if n==2:
5 return [2]
6 7.9219 MB 0.0000 MB elif n<2:
7 return []
8 7.9219 MB 0.0000 MB s=range(3,n+1,2)
9 7.9258 MB 0.0039 MB mroot = n ** 0.5
10 7.9258 MB 0.0000 MB half=(n+1)/2-1
11 7.9258 MB 0.0000 MB i=0
12 7.9258 MB 0.0000 MB m=3
13 7.9297 MB 0.0039 MB while m <= mroot:
14 7.9297 MB 0.0000 MB if s[i]:
15 7.9297 MB 0.0000 MB j=(m*m-3)/2
16 7.9258 MB -0.0039 MB s[j]=0
17 7.9297 MB 0.0039 MB while j<half:
18 7.9297 MB 0.0000 MB s[j]=0
19 7.9297 MB 0.0000 MB j+=m
20 7.9297 MB 0.0000 MB i=i+1
21 7.9297 MB 0.0000 MB m=2*i+3
22 7.9297 MB 0.0000 MB return [2]+[x for x in s if x]
line_profilerとmemory_profilerのIPythonショートカット
line_profilerとmemory_profilerのあまり知られていない機能として、どちらのプログラムもIPythonからアクセスできるコマンドショートカットを持っているということだ。IPythonのセッション内で以下のように実行するだけだ。
%load_ext memory_profiler
%load_ext line_profiler
これにより、コマンドラインの代わりとして使える%lprunと%mprunというマジックコマンドにアクセスできるようになる。大きな違いは、ここではプロファイルしたい関数を@profileデコレータで修飾する必要がないということだ。単に実行すれば、IPythonセッション内でプロファイリングが以下のように実行できる。
In [1]: from primes import primes
In [2]: %mprun -f primes primes(1000)
In [3]: %lprun -f primes primes(1000)
これで、コマンドのプロファイリングのためにソースコードを修正する必要がなくなるので、かなりの時間と手間が省ける。
メモリリークしているのはどこか？
cPythonインタプリタは、メモリ使用の経過を保持する主な方法として、参照カウントを使っている。これはつまり、各オブジェクトは、オブジェクトへの参照がどこかに保存された時にインクリメントされ、削除された時にデクリメントされるカウンタを持っているということだ。カウンタがゼロになった時、cPythonインタプリタはオブジェクトが既に使われていないものと判断し、オブジェクトを削除して確保されていたメモリを開放する。
メモリリークの多くは、プログラム内でオブジェクトがもう使われないにもかかわらずそのオブジェクトへの参照が残ってしまっている時に起きる。
こういった「メモリリーク」を見つける一番早い方法は、Marius Gedminas氏が書いたobjgraphという素晴らしいツールを使うことだ。このツールは、メモリ上にあるオブジェクトの数を見ることができ、オブジェクトへの参照を保持しているコード内の全ての場所を特定できる。
使い始めるにはまずobjgraphをインストールしよう。
pip install objgraph
インストールが終わったら、デバッガを起動する分をコードに書き込もう。
import pdb; pdb.set_trace()
どのオブジェクトが一番よく参照されているか
実行すると、プログラム内でよく使われているオブジェクト上位20個を見ることができる。
(pdb) import objgraph
(pdb) objgraph.show_most_common_types()
MyBigFatObject 20000
tuple 16938
function 4310
dict 2790
wrapper_descriptor 1181
builtin_function_or_method 934
weakref 764
list 634
method_descriptor 507
getset_descriptor 451
type 439
どのオブジェクトが生成あるいは削除されているか
開始から終了の間にどのオブジェクトが生成あるいは削除されているかも見ることができる。
(pdb) import objgraph
(pdb) objgraph.show_growth()
.
.
.
(pdb) objgraph.show_growth() # 前のshow_growth()の呼び出しから生成あるいは削除されたオブジェクトを表示する
traceback 4 +2
KeyboardInterrupt 1 +1
frame 24 +1
list 667 +1
tuple 16969 +1
リークしているオブジェクトへの参照はどれか
この方法でたどっていけば、特定のオブジェクトへの参照がどこで保持されているのかがわかることになる。以下のような簡単なプログラムで見てみよう。
x = [1]
y = [x, [x], {"a":x}]
import pdb; pdb.set_trace()
変数xへの参照を保持しているのが何かを知るために、objgraph.show_backref()関数を実行する。
(pdb) import objgraph
(pdb) objgraph.show_backref([x], filename="/tmp/backrefs.png")
コマンドの出力は以下のようなPNG画像として/tmp/backrefs.pngに保存される。
画像の下に赤文字で書かれているのが、調査しようとしているオブジェクトだ。それはシンボルxから1度だけ参照され、リストyから3回参照されている。xがメモリリークを引き起こしているオブジェクトだとすると、そこへの参照をたどっていくことで、なぜメモリが自動的に開放されないのかを知ることができる。
まとめると、objgraphは以下のことができる。
- プログラム内でメモリを多く確保しているN個のオブジェクトを表示する
- 一定の時間内で生成あるいは削除されたオブジェクトを表示する
- 指定したオブジェクトへの全ての参照を表示する
パフォーマンス計測における手間と求める精度のトレードオフ
この記事では、Pythonプログラムのパフォーマンスを計測するためのいくつかのツールの使い方を紹介した。これらのツールやテクニックで武装しておけば、メモリリークを追うためだけでなく速度のボトルネックを知るために必要なあらゆる情報を得ることができる。
他の多くのトピックと同じように、パフォーマンス計測はそれにかける手間と求める精度のトレードオフを探ることに他ならない。判断に迷う時には、その時の要求を満たす一番シンプルな方法を試してみよう。
