measure time

timelog.py

import inspect, builtins, threading, time
import itertools

class _Section:
    def __init__(self, log, ref, funcname, filename, lineno):
        self._log = log
        self._ref = ref
        self._funcname = funcname
        self._filename = filename
        self._lineno = lineno
        self._start = time.time()
        self._sent = False

    def __del__(self):
        if not self._sent:
            self.end()

    def end(self):
        self._log.emit(self._ref, self._funcname, self._filename, self._lineno, self._start, time.time())
        self._sent = True

class TimeLog:
    local = threading.local()
    def __init__(self, name, logger):
        self._logger = logger
        setattr(builtins, name, self)
        self._start = time.time()


    def get_refs(self):
        refs = getattr(self.local, 'refs', None)
        if refs is None:
            self.local.refs = refs = []
        return refs

    def begin(self, msg):
        func = inspect.currentframe().f_back.f_code
        caller = inspect.getframeinfo(inspect.stack()[1].frame)
        ref = object()
        with threading.RLock():
            self.get_refs().append((ref, msg))
        return _Section(self, ref, func.co_name, caller.filename, caller.lineno)

    def emit(self, ref, funcname, filename, lineno, start, end):
        msgs = []

        with threading.RLock():
            refs = self.get_refs()

            for i, (_ref, m) in enumerate(refs):
                msgs.append(m)
                if _ref == ref:
                    del refs[i]
                    break

        self._logger(f'{" | ".join(msgs)}: ' 
                     f'{end-start:.3f}sec '
                     f'({start-self._start:.3f}-{end-self._start:.3f}): '
                     f'{funcname}() {filename}:{lineno}')