Pythonでプロファイリングする

はじめに

とある処理の実行速度を計測したいと思った時に、いつもprint文を仕込むだけだったのですが、
ハイパフォーマンスPython 第2版 に載っていた方法が便利だったので下記にまとめます。

環境

・M1Mac
・OS:Ventura13.5

事前準備

sample.py というファイルに下記のsample_funcという関数を定義しました。

def sample_func():
    # 計測したい処理

1. print文

import time
from sample import sample_func

start_time = time.time()
sample_func()
end_time = time.time()

secs = end_time - start_time
print(sample_func.__name__ + " took", secs, "seconds")
    

出力結果

sample_func took 3.5176429748535156 seconds

2. デコレータを定義する

from functools import wraps

def timefn(fn):
    @wraps(fn)
    def measure_time(*args, **kwargs):
        t1 = time.time()
	result = fn(*args, **kwargs)
	t2 = time.time()
	print(f"@timefn: {fn.__name__} took {t2 - t1} seconds")
	return result
    return measure_time

# sample_funcにデコレータをつける
@timefn
def sample_func():
    # 計測したい処理

sample_func()を実行します。

出力結果

@timefn: sample_func took 3.5175788402557373 seconds

ちなみに、1より2の方が実行時間が短くなります。
理由は関数呼び出しのオーバーヘッドが少ないためです。

3. timeitモジュール

% python -m timeit -n 5 -r 1 -s "import module_name" "module_name.sample_func()"

n: ループの回数
r: テストの反復数

timeitモジュールは、一時的にガベージコレクションを無効にします。これが影響して、ガベージコレクションが働く実運用時と結果が異なることがあります。
https://docs.python.org/3.12/library/timeit.html#module-timeit

4. Unixのtimeコマンド

Pythonから離れ、Unix系システムの標準的なシステムユーティリティを使います。

% /usr/bin/time -p python sample.py
real 3.98
user 3.80
sys 0.03

--verbose フラグを使うとより詳細な内容が見れます。

% /usr/bin/time --verbose python sample.py

私の場合は、--verboseをつけてもエラーになったので、下記を実行しました。

% brew install gnu-time
% which gtime                                                      
/opt/homebrew/bin/gtime
% /opt/homebrew/bin/gtime --verbose python sample.py
        Command being timed: "python sample.py"
        User time (seconds): 3.73
        System time (seconds): 0.04
        Percent of CPU this job got: 96%
        Elapsed (wall clock) time (h:mm:ss or m:ss): 0:03.91
        Average shared text size (kbytes): 0
        Average unshared data size (kbytes): 0
        Average stack size (kbytes): 0
        Average total size (kbytes): 0
        Maximum resident set size (kbytes): 104784
        Average resident set size (kbytes): 0
        Major (requiring I/O) page faults: 50
        Minor (reclaiming a frame) page faults: 8103
        Voluntary context switches: 98
        Involuntary context switches: 375
        Swaps: 0
        File system inputs: 0
        File system outputs: 0
        Socket messages sent: 0
        Socket messages received: 0
        Signals delivered: 0
        Page size (bytes): 16384
        Exit status: 0

最後に

プロファイリング情報を追加すると否応なくコードは遅くなります。
プロファイリングの詳細度とスピードはトレードオフの関係のため、何でもかんでもプロファイリング情報を入れるのはやめましょう。

参考文献

ハイパフォーマンスPython 第2版