[Python 3] デコレータで実行時間を測る例のやつ

デコレータ実装での実行時間計測は、何も手を打たないと再帰関数でおかしな結果がでる

デコレータで実行時間を測る例のやつ (笑) を色々試してて気になった点や欲しい機能とかをいじってたらなんか後々使えそうな代物ができたので、docstring の書き方の練習も兼ねて公開してみることに。

• どこかで sp = SimpleProfiler() とかして、

  with sp:
      pass

  とするか、

  @sp.profile
  def foo():
      pass

  とすれば sp に測った実行時間やらカウントやらが記録されます。
• 後は時期を見計らって sp の各プロパティを読んで下さい。
  また、reset() で測った記録をリセットできます。
• Python インタプリタに直接食わせると、フィボナッチ関数 (キャッシュ無しと有り) をプロファイルするデモを行います。
• Python 3.5 (Debian Stretch に入ってるバージョン) あたりから使えると思います。
  当方ではとりあえずこれ書いている時点で最新の Raspbian で使えるやつ (3.5.3) と Windows版 (3.7.3) で開発・動作確認をしてあります。

ソースコード

使いたいという奇特な方は下記をコピペして simpleprofiler.py とかで各自保管して下さい。MITライセンスで扱って貰えば特に連絡などは要りません。

#!/usr/bin/env python3

# simpleprofiler.py - Simple profiler
#
# Copyright (c) 2019 Takayuki 'January June' Suwa
#
# This software is released under the MIT License.
#  https://opensource.org/licenses/mit-license.php

# PEP 8 (for lexical)
#000000001111111111222222222233333333334444444444555555555566666666667777777777
#234567890123456789012345678901234567890123456789012345678901234567890123456789

# PEP 8 (for text)
#00000000111111111122222222223333333333444444444455555555556666666666777
#23456789012345678901234567890123456789012345678901234567890123456789012

"""Simple profiler."""

try:
    from time import perf_counter_ns as _perf_counter_ns
    _clock = lambda: _perf_counter_ns() * 1e-9
except ImportError:
    try:
        from time import perf_counter as _clock
    except ImportError:
        from time import clock as _clock

class SimpleProfiler(object):
    """Simple profiler implementation, as context mananger."""

    __slots__ = "__started", "__elapsed_time", "__nested_level", \
            "__entered_count", "__checked_count", "__raised_count", \
            "__clicked_count"

    def __init__(self):
        self.__started, self.__elapsed_time, self.__nested_level, \
                self.__entered_count, self.__checked_count, \
                self.__raised_count, self.__clicked_count = 0.0, 0.0, 0, 0, 0,\
                0, 0

    def __repr__(self):
        return "%s(%fsec, %d, %d, %d, %d)" % (self.__class__.__name__,
                self.__elapsed_time, self.__entered_count, self.__checked_count,
                self.__raised_count, self.__clicked_count)

    @property
    def elapsed_time(self):
        """Return the accumulated value of the elapsed time in second
        around the region of the code, inside of this context.
        """
        return self.__elapsed_time

    @property
    def entered_count(self):
        """Return the accumulated value of the counter which is
        incremented by 1 when this context is entered.
        """
        return self.__entered_count

    @property
    def checked_count(self):
        """Return the accumulated value of the counter which is
        incremented by 1 when each time check has finished.
        """
        return self.__checked_count

    @property
    def raised_count(self):
        """Return the accumulated value of the counter which is
        incremented by 1 when each uncaught exception has been raised.
        """
        return self.__raised_count

    @property
    def clicked_count(self):
        """Return the accumulated value of the counter which is
        incremented by 1 when each 'click()' method has been called.
        """
        return self.__clicked_count

    def click(self):
        """Increment the number of times this method was called, by 1.
        """
        self.__clicked_count += 1

    def reset(self):
        """Reset the elapsed time and each counters, to the initial
        state.
        """
        self.__elapsed_time, self.__nested_level, self.__entered_count, \
                self.__checked_count, self.__raised_count, \
                self.__clicked_count = 0.0, 0, 0, 0, 0, 0

    def __enter__(self):
        """Enter this context.

        When re-entered an identical context, results of that time check
        and counting are ignored.
        """
        self.__entered_count += 1
        self.__nested_level += 1
        if self.__nested_level == 1:
            self.__started = _clock()

    def __exit__(self, exc_type, exc_val, exc_tb):
        """Exit from this context."""
        if self.__nested_level == 1:
            self.__elapsed_time += _clock() - self.__started
            self.__checked_count += 1
        if exc_type:
            self.__raised_count += 1
        self.__nested_level -= 1

    def profile(self, func):
        """Decorate the below function as inside of this context."""
        def wrapper(*args, **kwargs):
            with self:
                return func(*args, **kwargs)
        return wrapper

if __name__ == "__main__":
    print("\n[ SimpleProfiler demo ] Profiles the Fibonacci function!\n")
    p = SimpleProfiler()

    @p.profile
    def fib(x):
        return x if x < 2 else fib(x - 1) + fib(x - 2)
    def fib_demo():
        p.reset()
        try:
            for n in range(40):
                p.reset()
                print(" profiling fib(%d) in progress..."
                        % n, end="", flush=True)
                print("\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b=%d, %f seconds elapsed\n"
                      "   %d entered, %d checked, %d raised"
                        % (fib(n), p.elapsed_time, p.entered_count, \
                           p.checked_count, p.raised_count))
        except KeyboardInterrupt:
            print("\n***** aborted by user *****\n"
                  "   %f seconds elapsed (until abort)\n"
                  "   %d entered, %d checked, %d raised"
                    % (p.elapsed_time, p.entered_count, p.checked_count,
                       p.raised_count))
    print("[normal (uncached) version]")
    fib_demo()

    from functools import lru_cache
    @p.profile
    @lru_cache()
    def fib(x):
        return x if x < 2 else fib(x - 1) + fib(x - 2)
    print("\n[cached version]")
    fib_demo()