何番煎じかわかりませんが、もっとうまい方法を見つけるまでしばらくは何度も使い回しそうなのでメモ。

処理時間計測の課題

どんな言語を使っていても、作ったプログラムの実行時間を計測したい状況には度々遭遇します。

場当たり的には以下のように計測コードを埋め込んでコメントアウトをして……を繰り返しますが、測りたい部分が増えるにつれコードが汚くなっていきます。また、処理に関係ないコードが放置されているのは読み手の可読性を損なう可能性があります。

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段下がるのがちょっと気になるので、もっといい書き方あれば教えてください。。。