Функция отслеживания вызовов для регистрации времени

Question

Не уверен, возможно ли это в Python, но я пытаюсь профилировать большую функцию и указать, какие части ее обработки / ввода-вывода выполняются медленно. Я пытался написать пару функций декоратора; функция верхнего уровня для переноса профилируемой функции. И декораторы для некоторых из вложенных функций сообщают об их синхронизации, если пороговое значение превышено для декоратора верхнего уровня. Я не уверен, как я мог бы поделиться этим контекстом между декораторами.

Декоратор верхнего уровня

def time_stack(name, threshold=60000):
    def wrapper(f):
        def wrapped(*args, **kwargs):
            start = time_millis()
            f(*args, **kwargs)
            end = time_millis()
            if end - start > threshold:
                # Log out frame timings here
        return wrapped
    return wrapper

Для вложенных функций

def time_frame(name):
    def wrapper(f):
        def wrapped(*args, **kwargs):
            start = time_millis()
            f(*args, **kwargs)
            end = time_millis()
            t = end - start
            # Somehow remember this value for the outer time_stack to use if needed
        return wrapped
    return wrapper

Пример

@time_frame(name="do_some_io")
def do_some_io(string):
    # do some io

@time_frame(name="do_a_transform")
def do_a_transform(result):
    # do some transforming

@time_frame(name="do_some_caching")
def do_some_caching(stuff):
    # do some caching

@time_stack(name="search", threshold=100000):
def search(string):
    result = do_some_io(string)
    transformed = do_a_transform(result)
    return do_some_caching(transformed)

Здесь, если время выполнения поиска превысит 100000 мс, будет напечатано что-то вроде

search took 123456ms
    do_some_io: 23000ms
    do_a_transform: 13678ms
    do_some_caching: 86778ms

Я хотел бы передать объект через kwargs, чтобы отслеживать время, но тогда все функции в стеке вызовов должны иметь ** kwargs в своей подписи, и если есть способ достичь этого без необходимости сделать это было бы предпочтительнее.

Answer 1

Вы можете определить глобальный стек, в котором хранятся данные каждого таймфрейма. Он будет установлен на time_stack перед вызовом функции и будет сброшен в конце. Вы можете использовать его данные, если время прошло порог. Однако должен быть только один time_stack. Для нескольких функций time_stack должен быть стек, содержащий стеки. Эскиз этой идеи выглядит примерно так:

PROFILE_STACK = []
STACK_IS_SET = False
def time_stack(name, threshold=60000):
    def wrapper(f):
        def wrapped(*args, **kwargs):
            PROFILE_IS_SET = True
            start = time_millis()
            f(*args, **kwargs)
            end = time_millis()
            if end - start > threshold:
                # use PROFILE_STACK
            PROFILE_STACK.clear()
            STACK_IS_SET = False
        return wrapped
    return wrapper

И

def time_frame(name):
    def wrapper(f):
        def wrapped(*args, **kwargs):
            start = time_millis()
            f(*args, **kwargs)
            end = time_millis()
            t = end - start
            if STACK_IS_SET:
                PROFILE_STACK.append("SOMETHING")
            # Somehow remember this value for the outer time_stack to use if needed
        return wrapped
    return wrapper