profile, cProfile, pstats – Python プログラムのパフォーマンス解析¶
| 目的: | Python プログラムのパフォーマンス解析 |
|---|---|
| 利用できるバージョン: | 1.4 以上、このサンプルは Python 2.5 向け |
profile と cProfile モジュールは、Python プログラムがどのぐらいプロセッサのリソースを消費するかの統計を収集分析する API を提供します。
run()¶
profile モジュールの最も基本的な開始ポイントは run() です。それは引数として文字列のコードを受け取り、文字列のコードの実行時に実際のコードの実行に要した時間のレポートを作成します。
import profile
def fib(n):
# from http://en.literateprograms.org/Fibonacci_numbers_(Python)
if n == 0:
return 0
elif n == 1:
return 1
else:
return fib(n-1) + fib(n-2)
def fib_seq(n):
seq = [ ]
if n > 0:
seq.extend(fib_seq(n-1))
seq.append(fib(n))
return seq
print 'RAW'
print '=' * 80
profile.run('print fib_seq(20); print')
このフィボナッチ数列計算の再帰バージョン [1] は、大幅なパフォーマンス改善ができるのでプロファイルのデモをするのに特に便利です。標準のレポートフォーマットは、全体パフォーマンスの要約と実行したそれぞれの関数の詳細を表示します。
$ python profile_fibonacci_raw.py
RAW
================================================================================
[0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, 987, 1597, 2584, 4181, 6765]
57356 function calls (66 primitive calls) in 0.746 CPU seconds
Ordered by: standard name
ncalls tottime percall cumtime percall filename:lineno(function)
21 0.000 0.000 0.000 0.000 :0(append)
20 0.000 0.000 0.000 0.000 :0(extend)
1 0.001 0.001 0.001 0.001 :0(setprofile)
1 0.000 0.000 0.744 0.744 <string>:1(<module>)
1 0.000 0.000 0.746 0.746 profile:0(print fib_seq(20); print)
0 0.000 0.000 profile:0(profiler)
57291/21 0.743 0.000 0.743 0.035 profile_fibonacci_raw.py:13(fib)
21/1 0.001 0.000 0.744 0.744 profile_fibonacci_raw.py:22(fib_seq)
ご覧の通り、これは 57356 回の関数呼び出しと実行に 3/4 秒かかります。 プリミティブ な呼び出しは 66 回のみなので、57000 回の大半の呼び出しは再帰的に呼び出されたと分かります。処理に関する詳細は、関数毎に呼び出しの数(ncalls)、関数の実行に要した合計時間(tottime)、1回の呼び出し毎の時間(percall: tottime/ncalls)、1つの関数に要した累積時間(cumtime)、プリミティブな呼び出しの累積時間の割合(percall)に分類されます。
当然のことながら、この処理の大半の時間は何回も fib() の呼び出しにかかっています。再帰呼び出しの回数を減らすために memoize デコレータ [2] を追加すると、この関数のパフォーマンスに大きな影響があります。
import profile
class memoize:
# from http://avinashv.net/2008/04/python-decorators-syntactic-sugar/
def __init__(self, function):
self.function = function
self.memoized = {}
def __call__(self, *args):
try:
return self.memoized[args]
except KeyError:
self.memoized[args] = self.function(*args)
return self.memoized[args]
@memoize
def fib(n):
# from http://en.literateprograms.org/Fibonacci_numbers_(Python)
if n == 0:
return 0
elif n == 1:
return 1
else:
return fib(n-1) + fib(n-2)
def fib_seq(n):
seq = [ ]
if n > 0:
seq.extend(fib_seq(n-1))
seq.append(fib(n))
return seq
if __name__ == '__main__':
print 'MEMOIZED'
print '=' * 80
profile.run('print fib_seq(20); print')
再帰呼び出しの各レベルでフィボナッチ数を覚えておくことで、ほとんどの再帰呼び出しを行わずに 145 回に減らして、ほんの 0.003 秒になります。さらに fib() の ncalls 回数を見ると、その関数が 決して 再帰呼び出しされないことに注目してください。
$ python profile_fibonacci_memoized.py
MEMOIZED
================================================================================
[0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, 987, 1597, 2584, 4181, 6765]
145 function calls (87 primitive calls) in 0.003 CPU seconds
Ordered by: standard name
ncalls tottime percall cumtime percall filename:lineno(function)
21 0.000 0.000 0.000 0.000 :0(append)
20 0.000 0.000 0.000 0.000 :0(extend)
1 0.001 0.001 0.001 0.001 :0(setprofile)
1 0.000 0.000 0.002 0.002 <string>:1(<module>)
1 0.000 0.000 0.003 0.003 profile:0(print fib_seq(20); print)
0 0.000 0.000 profile:0(profiler)
59/21 0.001 0.000 0.001 0.000 profile_fibonacci_memoized.py:19(__call__)
21 0.000 0.000 0.001 0.000 profile_fibonacci_memoized.py:26(fib)
21/1 0.001 0.000 0.002 0.002 profile_fibonacci_memoized.py:36(fib_seq)
runctx()¶
場合によっては run() に複雑な式を渡すのではなく、シンプルな式を作成して runctx() からコンテキストを通してパラメータを渡すと簡単です。
import profile
from profile_fibonacci_memoized import fib, fib_seq
if __name__ == '__main__':
profile.runctx('print fib_seq(n); print', globals(), {'n':20})
このサンプルでは、”n” の値は runctx() へ渡すコードに直接含まれるのではなく、ローカル変数のコンテキストを通して渡されます。
$ python profile_runctx.py
[0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, 987, 1597, 2584, 4181, 6765]
145 function calls (87 primitive calls) in 0.003 CPU seconds
Ordered by: standard name
ncalls tottime percall cumtime percall filename:lineno(function)
21 0.000 0.000 0.000 0.000 :0(append)
20 0.000 0.000 0.000 0.000 :0(extend)
1 0.001 0.001 0.001 0.001 :0(setprofile)
1 0.000 0.000 0.002 0.002 <string>:1(<module>)
1 0.000 0.000 0.003 0.003 profile:0(print fib_seq(n); print)
0 0.000 0.000 profile:0(profiler)
59/21 0.001 0.000 0.001 0.000 profile_fibonacci_memoized.py:19(__call__)
21 0.000 0.000 0.001 0.000 profile_fibonacci_memoized.py:26(fib)
21/1 0.001 0.000 0.002 0.002 profile_fibonacci_memoized.py:36(fib_seq)
pstats: 統計を保存して扱う¶
profile 関数が作成する標準レポートはあまり柔軟ではありません。もし標準レポートが要望にあわないなら、 run() と runctx() が生成した raw プロファイルデータを保存して、 pstats から Stats クラスで個別に処理することで独自レポートを作成できます。
例えば、同じテストを何回か繰り返し実行して、その実行結果を組み合わせるのは次のようになります。
import profile
import pstats
from profile_fibonacci_memoized import fib, fib_seq
# stats ファイルを5セット作成する
filenames = []
for i in range(5):
filename = 'profile_stats_%d.stats' % i
profile.run('print %d, fib_seq(20)' % i, filename)
# 1つのオブジェクトへ5つの stats ファイルを全て読み込む
stats = pstats.Stats('profile_stats_0.stats')
for i in range(1, 5):
stats.add('profile_stats_%d.stats' % i)
# レポートのファイル名をクリーンアップする
stats.strip_dirs()
# 関数の累積時間によって統計をソートする
stats.sort_stats('cumulative')
stats.print_stats()
その実行結果のレポートは、その関数に要した累積時間の降順にソートされます。そして、表示上の横幅を節約するためにファイル名からディレクトリ名を削除します。
$ python profile_stats.py
0 [0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, 987, 1597, 2584, 4181, 6765]
1 [0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, 987, 1597, 2584, 4181, 6765]
2 [0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, 987, 1597, 2584, 4181, 6765]
3 [0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, 987, 1597, 2584, 4181, 6765]
4 [0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, 987, 1597, 2584, 4181, 6765]
Sun Aug 31 11:29:36 2008 profile_stats_0.stats
Sun Aug 31 11:29:36 2008 profile_stats_1.stats
Sun Aug 31 11:29:36 2008 profile_stats_2.stats
Sun Aug 31 11:29:36 2008 profile_stats_3.stats
Sun Aug 31 11:29:36 2008 profile_stats_4.stats
489 function calls (351 primitive calls) in 0.008 CPU seconds
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
5 0.000 0.000 0.007 0.001 <string>:1(<module>)
105/5 0.004 0.000 0.007 0.001 profile_fibonacci_memoized.py:36(fib_seq)
1 0.000 0.000 0.003 0.003 profile:0(print 0, fib_seq(20))
143/105 0.001 0.000 0.002 0.000 profile_fibonacci_memoized.py:19(__call__)
1 0.000 0.000 0.001 0.001 profile:0(print 4, fib_seq(20))
1 0.000 0.000 0.001 0.001 profile:0(print 1, fib_seq(20))
1 0.000 0.000 0.001 0.001 profile:0(print 2, fib_seq(20))
1 0.000 0.000 0.001 0.001 profile:0(print 3, fib_seq(20))
21 0.000 0.000 0.001 0.000 profile_fibonacci_memoized.py:26(fib)
100 0.001 0.000 0.001 0.000 :0(extend)
105 0.001 0.000 0.001 0.000 :0(append)
5 0.001 0.000 0.001 0.000 :0(setprofile)
0 0.000 0.000 profile:0(profiler)
レポートコンテンツを制限する¶
いまは fib() と fib_seq() のパフォーマンスを調べているので、 filename:lineno(function) にマッチする正規表現を使用してそういった関数のみを含めるように結果レポートを制限できます。
import profile
import pstats
from profile_fibonacci_memoized import fib, fib_seq
# 1つのオブジェクトへ5つの stats ファイルを全て読み込む
stats = pstats.Stats('profile_stats_0.stats')
for i in range(1, 5):
stats.add('profile_stats_%d.stats' % i)
stats.strip_dirs()
stats.sort_stats('cumulative')
# "(fib" を含む行のみに出力を制限する
stats.print_stats('\(fib')
この正規表現は関数名の部分にマッチするようにリテラルの左括弧 (() を含めます。
$ python profile_stats_restricted.py
Sun Aug 31 11:29:36 2008 profile_stats_0.stats
Sun Aug 31 11:29:36 2008 profile_stats_1.stats
Sun Aug 31 11:29:36 2008 profile_stats_2.stats
Sun Aug 31 11:29:36 2008 profile_stats_3.stats
Sun Aug 31 11:29:36 2008 profile_stats_4.stats
489 function calls (351 primitive calls) in 0.008 CPU seconds
Ordered by: cumulative time
List reduced from 13 to 2 due to restriction <'\\(fib'>
ncalls tottime percall cumtime percall filename:lineno(function)
105/5 0.004 0.000 0.007 0.001 profile_fibonacci_memoized.py:36(fib_seq)
21 0.000 0.000 0.001 0.000 profile_fibonacci_memoized.py:26(fib)
呼び出し / 呼び出される関数のグループ¶
さらに Stats は、関数の呼び出し側と呼び出される側を表示するメソッドを提供します。
import profile
import pstats
from profile_fibonacci_memoized import fib, fib_seq
# 1つのオブジェクトへ5つの stats ファイルを全て読み込む
stats = pstats.Stats('profile_stats_0.stats')
for i in range(1, 5):
stats.add('profile_stats_%d.stats' % i)
stats.strip_dirs()
stats.sort_stats('cumulative')
print 'INCOMING CALLERS:'
stats.print_callers('\(fib')
print 'OUTGOING CALLEES:'
stats.print_callees('\(fib')
print_callers() と print_callees() への引数は print_stats() の引数と同様に正規表現で出力を制限できます。その結果レポートは呼び出し側と呼び出される側の累積時間を表示します。
$ python profile_stats_callers.py
INCOMING CALLERS:
Ordered by: cumulative time
List reduced from 13 to 2 due to restriction <'\\(fib'>
Function was called by...
profile_fibonacci_memoized.py:36(fib_seq) <- <string>:1(<module>)(5) 0.007
profile_fibonacci_memoized.py:36(fib_seq)(100) 0.007
profile_fibonacci_memoized.py:26(fib) <- profile_fibonacci_memoized.py:19(__call__)(21) 0.002
OUTGOING CALLEES:
Ordered by: cumulative time
List reduced from 13 to 2 due to restriction <'\\(fib'>
Function called...
profile_fibonacci_memoized.py:36(fib_seq) -> :0(append)(105) 0.001
:0(extend)(100) 0.001
profile_fibonacci_memoized.py:19(__call__)(105) 0.002
profile_fibonacci_memoized.py:36(fib_seq)(100) 0.007
profile_fibonacci_memoized.py:26(fib) -> profile_fibonacci_memoized.py:19(__call__)(38) 0.002
See also
- profile and cProfile
- 本モジュールの標準ライブラリドキュメント
- pstats
- pstats の標準ライブラリドキュメント
- Gprof2Dot
- プロファイル出力データの視覚化ツール
| [1] | Fibonacci numbers (Python) - LiteratePrograms via http://en.literateprograms.org/Fibonacci_numbers_(Python) |
| [2] | Python Decorators: Syntactic Sugar | avinash.vora from http://avinashv.net/2008/04/python-decorators-syntactic-sugar/ |
