Yakstは、海外の役立つブログ記事などを人力で翻訳して公開するプロジェクトです。
6年弱前投稿 修正あり

Pythonスクリプトのパフォーマンス計測ガイド

Pythonスクリプトの速度を計測し、そのボトルネックを探る。さらに、メモリ使用量、メモリリークの原因特定までの調査方法を解説する。

原文
A guide to analyzing Python performance « Huy Nguyen (English)
翻訳依頼者
D98ee74ffe0fafbdc83b23907dda3665
翻訳者
D98ee74ffe0fafbdc83b23907dda3665 doublemarket
原著者への翻訳報告
未報告


あなたが書いたすべての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_profilermemory_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に保存される。

back reference

画像の下に赤文字で書かれているのが、調査しようとしているオブジェクトだ。それはシンボルxから1度だけ参照され、リストyから3回参照されている。xがメモリリークを引き起こしているオブジェクトだとすると、そこへの参照をたどっていくことで、なぜメモリが自動的に開放されないのかを知ることができる。

まとめると、objgraphは以下のことができる。

  • プログラム内でメモリを多く確保しているN個のオブジェクトを表示する
  • 一定の時間内で生成あるいは削除されたオブジェクトを表示する
  • 指定したオブジェクトへの全ての参照を表示する

パフォーマンス計測における手間と求める精度のトレードオフ

この記事では、Pythonプログラムのパフォーマンスを計測するためのいくつかのツールの使い方を紹介した。これらのツールやテクニックで武装しておけば、メモリリークを追うためだけでなく速度のボトルネックを知るために必要なあらゆる情報を得ることができる。

他の多くのトピックと同じように、パフォーマンス計測はそれにかける手間と求める精度のトレードオフを探ることに他ならない。判断に迷う時には、その時の要求を満たす一番シンプルな方法を試してみよう。

次の記事
これが私の好きなMySQL 5.6の新機能。あなたの好きな機能は?
前の記事
プロセスとスレッドの違いとは?

同じタグの付いた翻訳済み記事

Feed small 記事フィード

新着記事Twitterアカウント

新着翻訳リクエストTwitterアカウント