profile --- 純粋な Python によるプロファイラ

ソースコード: Lib/profile.py


バージョン 3.15 で非推奨、バージョン 3.17 で削除予定.

profile モジュールは非推奨で、Python 3.17 で削除されます。 代わりに profiling.tracing を使ってください。

profile モジュールは、決定論的プロファイラを純粋な Python で実装したものです。 プロファイラの内部構造を理解したり、サブクラスで動作を拡張したりするのには便利ですが、純粋な Python の実装なので、C で実装された profiling.tracing モジュールよりも大きなオーバーヘッドが生じます。

ほとんどのプロファイリング用途では、次を使ってください。

移行

profile から profiling.tracing への移行は簡単です。 API には互換性があります。

# 従来の方法 (非推奨)
import profile
profile.run('my_function()')

# 新しい方法 (推奨)
import profiling.tracing
profiling.tracing.run('my_function()')

ほとんどのコードは、import profile を import profiling.tracing に置き換え、コード全体で profile の代わりに profiling.tracing を使うことで簡単に移行できます。

注釈

cProfile モジュールは、profiling.tracing の後方互換性のための別名として引き続き利用できます。 import cProfile を使う既存のコードは、変更せずに動作します。

profile と profiling.tracing モジュールのリファレンス

profile と profiling.tracing は、どちらも次の関数を提供します。

profile.run(command, filename=None, sort=-1)

この関数は exec() 関数に渡せる一つの引数と、オプション引数としてファイル名を指定できます。全ての場合でこのルーチンは以下を実行します:

exec(command, __main__.__dict__, __main__.__dict__)

そして実行結果からプロファイル情報を収集します。 ファイル名が指定されていない場合は、 Stats のインスタンスが自動的に作られ、簡単なプロファイルレポートが表示されます。 sort が指定されている場合は、 Stats インスタンスに渡され、結果をどのように並び替えるかを制御します。

profile.runctx(command, globals, locals, filename=None, sort=-1)

この関数は run() と似ていますが、command 文字列の実行に使うグローバル名前空間とローカル名前空間のマッピングを指定する引数が追加されています。 次のコードを実行します。

exec(command, globals, locals)

そしてプロファイル統計情報を run() 同様に収集します。

class profile.Profile(timer=None, timeunit=0.0, subcalls=True, builtins=True)

このクラスは通常、profiling.tracing.run() 関数よりもプロファイリングを細かく制御する必要がある場合にだけ使います。

timer 引数に、コードの実行時間を計測するためのカスタムな時刻取得用関数を渡せます。これは現在時刻を表す単一の数値を返す関数でなければなりません。もしこれが整数を返す関数ならば、 timeunit には単位時間当たりの実際の持続時間を指定します。たとえば関数が 1000 分の 1 秒単位で計測した時間を返すとすると、 timeunit は .001 でしょう。

Profile クラスを直接使うと、プロファイルデータをファイルに書き出すことなしに結果をフォーマット出来ます:

import profiling.tracing
import pstats
import io
from pstats import SortKey

pr = profiling.tracing.Profile()
pr.enable()
# ... 処理を行う ...
pr.disable()
s = io.StringIO()
sortby = SortKey.CUMULATIVE
ps = pstats.Stats(pr, stream=s).sort_stats(sortby)
ps.print_stats()
print(s.getvalue())

Profile クラスはコンテキストマネージャーとしても使えます (profiling.tracing のみの機能で、非推奨の profile モジュールでは使えません。 コンテキストマネージャ型 を参照してください)。

import profiling.tracing

with profiling.tracing.Profile() as pr:
    # ... 処理を行う ...

    pr.print_stats()

バージョン 3.8 で変更: コンテキストマネージャーサポートが追加されました。

enable()

プロファイリングデータの収集を開始します。 profiling.tracing のみの機能です。

disable()

プロファイリングデータの収集を停止します。 profiling.tracing のみの機能です。

create_stats()

プロファイリングデータの収集を停止し、現在のプロファイルとして結果を内部で記録します。

print_stats(sort=-1)

現在のプロファイルに基づいて Stats オブジェクトを作成し、結果を標準出力に出力します。

sort 引数は、表示する統計情報のソート順を指定します。 pstats.Stats.sort_stats() と同じように、単一のキー、または複数のキーでソートするためのキーのタプルを受け取ります。

Added in version 3.13: print_stats() がキーのタプルを受け取るようになりました。

dump_stats(filename)

現在のプロファイルの結果を filename に書き出します。

run(cmd)

exec() を用いて cmd をプロファイルします。

runctx(cmd, globals, locals)

exec() を用いて指定されたグローバルおよびローカルな環境で cmd をプロファイルします。

runcall(func, /, *args, **kwargs)

func(*args, **kwargs) をプロファイルします。

Note that profiling will only work if the called command/function actually returns. If the interpreter is terminated (e.g. via a sys.exit() call during the called command/function execution) no profiling results will be printed.

profiling.tracing との違い

profile モジュールは、次の点で profiling.tracing と異なります。

大きなオーバーヘッド。 純粋な Python による実装は C による実装よりも大幅に遅いため、長時間動作するプログラムや性能が重要なコードのプロファイリングには適していません。

補正への対応。 profile モジュールは、プロファイリングのオーバーヘッドを補うための補正に対応しています。 profiling.tracing は C による実装でオーバーヘッドが無視できるほど小さいため、補正は不要です。

独自の時刻取得用関数。 どちらのモジュールも独自の時刻取得用関数に対応していますが、profile は os.times() のようにタプルを返す関数を受け取れる一方、profiling.tracing は単一の数値を返す関数を必要とします。

サブクラス化。 純粋な Python による実装はサブクラス化しやすく、独自のプロファイリング動作を実装するための拡張も容易です。

決定論的プロファイリングとは

Deterministic profiling is meant to reflect the fact that all function call, function return, and exception events are monitored, and precise timings are made for the intervals between these events (during which time the user's code is executing). In contrast, statistical profiling (which is provided by the profiling.sampling module) periodically samples the effective instruction pointer, and deduces where time is being spent. The latter technique traditionally involves less overhead (as the code does not need to be instrumented), but provides only relative indications of where time is being spent.

Python の場合、実行中は必ずインタプリタが動作しているため、決定論的プロファイリングを行うために計測用のコードを追加する必要はありません。 Python は自動的に各イベントに フック (オプションのコールバック) を提供します。加えて Python のインタプリタという性質によって、実行時に大きなオーバーヘッドを伴う傾向がありますが、それに比べると一般的なアプリケーションでは決定論的プロファイリングで追加される処理のオーバーヘッドは少ない傾向にあります。結果的に、決定論的プロファイリングは少ないコストで Python プログラムの実行時間に関する詳細な統計を得られる方法となっているのです。

呼び出し回数はコード中のバグ発見にも使用できます (とんでもない数の呼び出しが行われている部分)。インライン拡張の対象とすべき部分を見つけるためにも使えます (呼び出し頻度の高い部分)。内部時間の統計は、注意深く最適化すべき"ホットループ"の発見にも役立ちます。累積時間の統計は、アルゴリズム選択に関連した高レベルのエラー検知に役立ちます。なお、このプロファイラは再帰的なアルゴリズム実装の累計時間を計ることが可能で、通常のループを使った実装と直接比較することもできるようになっています。

制限事項

一つの制限はタイミング情報の正確さに関するものです。 決定論的プロファイラには正確さに関する根本的問題があります。 最も明白な制限は、 (一般に) "クロック"は .001 秒の精度しかないということです。 これ以上の精度で計測することはできません。 十分な回数の測定を行えば、「誤差」は平均化される傾向があります。 この最初の誤差を取り除いたとしても、それがまた別の誤差を引き起こす原因となります。

もう一つの問題として、イベントを検知してからプロファイラがその時刻を実際に 取得 するまでに "いくらかの時間がかかる" ことです。 同様に、イベントハンドラが終了する時にも、時刻を取得して (そしてその値を保存して) から、ユーザコードが処理を再開するまでの間に遅延が発生します。 結果的に多く呼び出される関数または多数の関数を呼び出す関数の情報にはこの種の誤差が蓄積する傾向にあります。 このようにして蓄積される誤差は、典型的にはクロックの精度を下回ります (1クロック以下) が、一方でこの時間が累計して非常に大きな値になることも あり得ます 。

この問題は、オーバーヘッドの小さい profiling.tracing よりも、非推奨の profile モジュールで重要になります。 このため、profile は、使用するプラットフォームに合わせて補正を行い、この誤差を確率的に (平均として) 取り除く手段を提供しています。 補正後のプロファイラは (最小二乗の意味で) より正確になりますが、ときには負の値を出すことがあります (呼び出し回数が極端に少なく、確率の神様が味方してくれない場合などです :-) )。 プロファイルに負の値があっても、驚く 必要はありません。 これはプロファイラを補正した場合に だけ 起こるはずで、結果は補正しない場合よりも実際には改善されています。

キャリブレーション (補正)

profile モジュールのプロファイラは、時刻取得用関数の呼び出しと結果の保存によるオーバーヘッドを補うため、各イベントの処理時間から定数を差し引きます。 デフォルトでは、この定数は 0 です。 次の手順で、使用するプラットフォームにより適した定数を求められます (制限事項 を参照)。

import profile
pr = profile.Profile()
for i in range(5):
    print(pr.calibrate(10000))

calibrate メソッドは引数として与えられた数だけ Python の呼び出しを行います。直接呼び出す場合と、プロファイラを使って呼び出す場合の両方が実施され、それぞれの時間が計測されます。その結果、プロファイラのイベントに隠されたオーバーヘッドが計算され、その値は浮動小数として返されます。たとえば、 1.8 GHz の Intel Core i5 で macOS を使用、 Python の time.process_time() をタイマとして使った場合、値はおよそ 4.04e-6 となります。

この手順の目的は、十分に安定した結果を得ることです。 非常に 早いコンピュータを使う場合、もしくはタイマの分解能が低いな場合は、一定の結果を得るために引数に 100000 や 1000000 といった大きな値を指定する必要があるかもしれません。

一定の結果が得られたら、それを使う方法には3通りあります:

import profile

# 1. これ以降に作成するすべての Profile インスタンスに、計算した補正値を適用します。
profile.Profile.bias = your_computed_bias

# 2. 特定の Profile インスタンスに、計算した補正値を適用します。
pr = profile.Profile()
pr.bias = your_computed_bias

# 3. インスタンスのコンストラクターに、計算した補正値を指定します。
pr = profile.Profile(bias=your_computed_bias)

選択肢がある場合は、補正値は小さめに設定した方が良いでしょう。プロファイルの結果に負の値が表われる"頻度が低く"なるはずです。

カスタムな時刻取得用関数を使う

プロファイラが時刻を取得する方法を変更したいなら (たとえば、実測時間やプロセスの経過時間を使いたい場合)、時刻取得用の関数を Profile クラスのコンストラクタに指定することができます:

pr = profile.Profile(your_time_func)

作成したプロファイラは your_time_func を呼び出します。 その戻り値の解釈は、profile.Profile と profiling.tracing.Profile のどちらを使うかによって異なります。

profile.Profile

your_time_func() は単一の数値、あるいは (os.times() と同じように) その合計が累計時間を示すリストを返すようになっていなければなりません。関数が1つの数値、あるいは長さ2の数値のリストを返すようになっていれば、ディスパッチルーチンには特別な高速化バージョンが使われます。

選択した時刻取得用関数に合わせてプロファイラクラスを補正する必要があることに注意してください (キャリブレーション (補正) を参照)。 ほとんどのマシンでは、整数を一つ返す関数が、プロファイリング中のオーバーヘッドを最も抑えられます。 (os.times() は浮動小数点数のタプルを返すため、かなり 不利です。) より適した時刻取得用関数にすっきり置き換えるには、派生クラスを作り、その関数の呼び出しに最も適したディスパッチメソッドと、適切な補正定数を組み込んでください。

profiling.tracing.Profile

your_time_func() は単一の数値を返すようになっていなければなりません。単一の整数を返すのであれば、クラスコンストラクタの第二引数に単位時間当たりの実際の持続時間を渡せます。例えば your_integer_time_func が 1000 分の 1 秒単位で計測した時間を返すとすると、 Profile インスタンスを以下のように構築出来ます:

pr = profiling.tracing.Profile(your_integer_time_func, 0.001)

profiling.tracing.Profile クラスは補正できないため、独自の時刻取得用関数は慎重に使い、可能な限り高速にする必要があります。 最良の結果を得るには、内部モジュール _lsprof の C ソースにその関数を組み込む必要があるかもしれません。

Python 3.3 で time に、プロセス時間や実時間の精密な計測に使える新しい関数が追加されました。 例えば、 time.perf_counter() を参照してください。

参考

profiling

Python のプロファイリングツールの概要。

profiling.tracing

このモジュールの代わりに使うことを推奨するモジュール。

pstats

プロファイルデータの統計分析と整形。