処理時間計測の基本

処理時間を計測するにあたり、基本的な考え方は「処理終了時刻-処理開始時刻」です。 Pythonで処理時間を計測する場合、timeモジュールのperf_counterがよく使用されます。
例えば、下記の様な使い方をすることで処理時間を計測することが可能です。

import time

if __name__ == '__main__':
    # 計測開始
    start_time = time.perf_counter()

    # 計測対象
    time.sleep(5)

    # 計測終了
    end_time = time.perf_counter()

    # 処理時間算出(sec)
    elapsed_time = end_time - start_time
    print(elapsed_time)

perf_counterは単位が秒ですが、process_time_ns 関数を使用することでナノ秒単位で取得することも可能です。

処理時間計測用クラスの作成

上記の様な方法でもいいのですが、毎回処理時間を算出するのが面倒な場合、下記のように計測用クラスを作成することでstart、endを呼び出すだけで計測が可能となります。
また、計測開始時間をリストに格納し保持しておくことで、一度に様々な個所の時間を計測することが可能です。

import time

class Performance:
    def __init__(self):
        # 計測開始時間を格納しておくためのリスト初期化
        self.start_time_list = []

    def start(self):
        # 計測会時間を格納
        self.start_time_list.append(time.perf_counter())

    def end(self, msg):
        # startの呼び出し回数とendの呼び出し回数が一致しているかどうかチェック。リストが空かどうかで判定
        if len(self.start_time_list) == 0:
            print('startの呼び出し回数とendの呼び出し回数が一致していません')
            return
        # 開始時間の取得（リストの最後の値を取得）
        start_time = self.start_time_list.pop(-1)
        # 終了
        end_time = time.perf_counter()
        # 経過時間算出
        elapsed_time = end_time - start_time
        print(msg + ':' + str(elapsed_time))

if __name__ == '__main__':
    performance = Performance()
    # 処理全体の時間を計測するためのstart呼び出し
    performance.start()

    # 1回目のsleepを計測するためのstart呼び出し
    performance.start()
    time.sleep(5)
    # 1回目のsleepを計測するためのend呼び出し
    performance.end('1回目のsleep')

    # 2回目のsleepを計測するためのstart呼び出し
    performance.start()
    time.sleep(5)
    # 2回目のsleepを計測するためのend呼び出し
    performance.end('2回目のsleep')

    # 処理全体の時間を計測するためのend呼び出し
    performance.end('全体の時間')

デコレータの作成

関数単位で計測したい場合は、デコレータを活用するとよりすっきりと記述することが出来ます。
下記の様なデコレータを作成し、計測したい関数などの宣言の前に@デコレータ名とすることで計測可能です。

import time

def performance(f):
    def _wrapper(*args, **keywords):
        # 計測開始
        start_time = time.perf_counter()

        # 対象関数の実行
        ret = f(*args, **keywords)

        # 計測終了
        end_time = time.perf_counter()

        # 処理時間算出(s)
        elapsed_time = end_time - start_time
        # print文で関数名と処理時間を出力
        print(f.__name__, elapsed_time)

        return ret

    return _wrapper

@performance
def test_func():
    time.sleep(5)

if __name__ == '__main__':
    test_func()