このページではPythonで処理時間を計測する方法について解説します。
perf_counterとprocess_time
Pythonコード中で処理時間を計測する方法として、timeモジュールのperf_counterとprocess_timeを使用する方法があります。どちらも２点間の処理時間を差で求めます。
perf_counter
time.perf_counter()の戻り値でパフォーマンスカウンターを得ることができます。単位は秒となります。前述の通り２点間の処理時間を求める場合は終了時点の時間から開始時間の時間を引き算することで求めます。以下はperf_counterを使用したサンプルコードです。
import time # 開始 start_time = time.perf_counter() # ダミー処理 time.sleep(1) # 修了 end_time = time.perf_counter() # 経過時間を出力(秒) elapsed_time = end_time - start_time print(elapsed_time)
上のコードの実行結果の通り、単純な実行時間を求めることができます。
process_time
一方process_timeはCPU処理時間を求めることが可能です。先程のコードを修正してみましょう。
以下はprocess_timeを使用したサンプルコードです。
import time # 開始 start_time = time.process_time() # ダミー処理 time.sleep(1) # 修了 end_time = time.process_time() # 経過時間を出力(秒) elapsed_time = end_time - start_time print(elapsed_time)
sleepした時間が計上されていないことが確認できます。CPUの使用時間を計測する場合はprocess_timeを使用します。I/Oバウンドな処理かどうかを判別したい場合はperf_counterとprocess_time両方で計測して値を比較することになります。
デコレータの活用
計測用のコード修正が多岐にわたると修正が面倒であるため、計測対象の関数に対してデコーレータを用意するという方法がよくとられます。以下のコードはデコレータを使用して関数の開始終了時間をprint出力しています。PyPIに同様のライブラリが多くありますので探してみるのも一つの方法です。
import time
def print_proc_time(f):
""" 計測デコレータ """
def print_proc_time_func(*args, **kwargs):
# 開始
start_time = time.process_time()
# 関数実行
return_val = f(*args, **kwargs)
# 修了
end_time = time.process_time()
# 関数名と経過時間を出力(秒)
elapsed_time = end_time - start_time
print(f.__name__, elapsed_time)
# 戻り値を返す
return return_val
return print_proc_time_func
@print_proc_time
def calc_mass(n, m):
"""" 計測対象関数 """
for i in range(n):
x = i ** m
calc_mass(3000000, 3)
プロファイラ
プログラムを実際に実行し、処理時間等情報を収集ツールのことをプロファイラと呼びます。
これまでコードを記述する計測方法について解説しましたが、開発現場ではまず関数単位で処理の遅い箇所を特定するためにプロファイラを使用し、その後詳細な調査が必要であれば先程紹介したperf_counterとprocess_timeを使用する、という流れが多いかと思います。Pythonにはプロファイラが本体にcProfileという組み込みモジュールとして提供されています。
https://docs.python.org/ja/3/library/profile.html
以下のコマンドでプロファイラを使用することが可能で、関数ごとの実行時間を参照することが可能です。
実行すると以下のような結果を得ることができます。
6 function calls in 0.268 seconds
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 0.268 0.268 {built-in method builtins.exec}
1 0.000 0.000 0.268 0.268 sample.py:1(<module>)
1 0.000 0.000 0.268 0.268 sample.py:11(main)
1 0.206 0.206 0.206 0.206 sample.py:1(calc_mass1)
1 0.062 0.062 0.062 0.062 sample.py:6(calc_mass2)
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
以下、それぞれの項目に関する説明を公式から引用しました。
- ncalls:呼び出し回数
- tottime:与えられた関数に消費された合計時間 (sub-function の呼び出しで消費された時間は除外されています)
- percall:`tottime` を `ncalls` で割った値
- cumtime:この関数と全ての subfunction に消費された累積時間 (起動から終了まで)。この数字は再帰関数についても正確です。
- percall `cumtime` をプリミティブな呼び出し回数で割った値
- filename:lineno(function):その関数のファイル名、行番号、関数名
補足 timeit
Pythonには計測用にtimeitというモジュールが提供されています。個人的にあまり使い勝手が良いとは思えず使うことがあまりないのですが、比較的著名なモジュールなので最後に補足として簡単な使用方法を紹介します。
timeitは引数に計測したい処理を文字列で指定すると1000000回実行した場合の実行時間が返されます。
処理の文字列以外に以下の引数を設定することができます。
- number：処理回数。デフォルトは1000000回なので指定しないとかなり時間がかかります。
- timer：使用するタイマーの種類。デフォルトではtime.perf_counter。time.process_timeを指定するとsleep時間等CPUを使用しない時間は除外されます。
- globals：モジュール変数を使用する場合はglobals()を指定します。
以下はtimeitを使用した計測のサンプルです。1番目の引数は関数呼び出しの処理を文字列で指定しています。
import timeit
def calc_mass(n, m):
"""" 計測対象関数 """
for i in range(n):
x = i ** m
elapsed_time = timeit.timeit('calc_mass(10000, 3)', number=1000)
print(elapsed_time)
