何番煎じかわかりませんが、もっとうまい方法を見つけるまでしばらくは何度も使い回しそうなのでメモ。
処理時間計測の課題
どんな言語を使っていても、作ったプログラムの実行時間を計測したい状況には度々遭遇します。
場当たり的には以下のように計測コードを埋め込んでコメントアウトをして……を繰り返しますが、測りたい部分が増えるにつれコードが汚くなっていきます。また、処理に関係ないコードが放置されているのは読み手の可読性を損なう可能性があります。
import time
# あるあるソース
t1 = time.time()
・・・(そこそこ時間がかかる処理)・・・
t2 = time.time()
print(f"{t2 - t1}秒")
Pythonの場合は、with構文とデコレータを使うことで比較的コードをきれいにしたまま時間計測のコードを組み込むことができます。
With構文を使った例
次のようなクラスを定義します。
import time
import logging
class Timer:
def __init__(self, name):
self.name = name
def __enter__(self):
self.t_start = time.time()
def __exit__(self, ex_type, ex_value, trace):
self.t_end = time.time()
logger.debug(f"{self.name}: {self.t_end - self.t_start} 秒")
__enter__
と__exit__
を定義することで、作ったクラスをwith構文で利用できるようになり、with構文に入ったときに__enter__
が呼ばれ、with構文から抜けたときに__exit__
が呼ばれるようになります。この仕組みを利用し、__enter__
で計測開始時間、__exit__
で計測終了時間を取得し、ついでにログに出力するようにすることで、時間計測とログ出力を共通化できるようになります。
例えば次のように使用します。
with Timer("time.sleep の時間計測"):
logger.info("1秒間寝ます。")
time.sleep(1)
logger.info("起きました。")
この場合、次のような出力が得られます。
2023-03-28 21:10:11,199 [INFO ] 1秒間寝ます。
2023-03-28 21:10:12,207 [INFO ] 起きました。
2023-03-28 21:10:12,208 [DEBUG ] time.sleep の時間計測: 1.009138584136963 秒
デコレータを使った例
時間計測を関数単位で行いたい場合は、デコレータを使ったほうがより簡潔に記述できます。
まずデコレータを作成します。ここでも先程作ったTimerクラスを使用していますが、直接time.time()
を呼んでしまってもいいです。
def timer_dec(func):
def wrapper(*args, **kwargs):
with Timer(f"関数 {func.__name__} の実行時間"):
return func(*args, **kwargs)
return wrapper
デコレータを使うときは、関数定義の直前に@
記号を使用してデコレータの呼び出しを宣言します。
@timer_dec
def sleep():
logger.info("1秒間寝ます。")
time.sleep(1)
logger.info("起きました。")
この場合も、次のような出力が得られます。便利。
2023-03-28 21:10:12,209 [INFO ] 1秒間寝ます。
2023-03-28 21:10:13,219 [INFO ] 起きました。
2023-03-28 21:10:13,220 [DEBUG ] 関数 sleep の実行時間: 1.0108270645141602 秒
おわりに
with構文の場合インデントが1段下がるのがちょっと気になるので、もっといい書き方あれば教えてください。。。