Декоратор, который профилирует вызов метода и регистрирует результат профилирования

Question

Я хочу создать декоратор, который профилирует метод и регистрирует результат. Как это может быть сделано?

Answer 1

Декоратор будет выглядеть примерно так:

import time
import logging

def profile(func):
    def wrap(*args, **kwargs):
        started_at = time.time()
        result = func(*args, **kwargs)
        logging.info(time.time() - started_at)
        return result

    return wrap

@profile
def foo():
    pass

В любом случае, если вы хотите провести серьезное профилирование, я бы предложил вам использовать профиль или пакеты cProfile.

Answer 2

Если вы хотите правильное профилирование вместо времени, вы можете использовать недокументированную функцию cProfile (из этого вопроса):

import cProfile

def profileit(func):
    def wrapper(*args, **kwargs):
        datafn = func.__name__ + ".profile" # Name the data file sensibly
        prof = cProfile.Profile()
        retval = prof.runcall(func, *args, **kwargs)
        prof.dump_stats(datafn)
        return retval

    return wrapper

@profileit
def function_you_want_to_profile(...)
    ...

Если вы хотите больше контролировать имя файла, вам понадобится еще один уровень косвенности:

import cProfile

def profileit(name):
    def inner(func):
        def wrapper(*args, **kwargs):
            prof = cProfile.Profile()
            retval = prof.runcall(func, *args, **kwargs)
            # Note use of name from outer scope
            prof.dump_stats(name)
            return retval
        return wrapper
    return inner

@profileit("profile_for_func1_001")
def func1(...)
    ...

Это выглядит сложно, но если вы будете следовать ему шаг за шагом (и заметите разницу в вызове профилировщика), это должно стать ясным.

Answer 3

Мне нравится ответ @detly. Но иногда проблема заключается в использовании SnakeViz для просмотра результата.

Я сделал немного другую версию, которая записывает результат в виде текста в тот же файл:

import cProfile, pstats, io

def profileit(func):
    def wrapper(*args, **kwargs):
        datafn = func.__name__ + ".profile" # Name the data file sensibly
        prof = cProfile.Profile()
        retval = prof.runcall(func, *args, **kwargs)
        s = io.StringIO()
        sortby = 'cumulative'
        ps = pstats.Stats(prof, stream=s).sort_stats(sortby)
        ps.print_stats()
        with open(datafn, 'w') as perf_file:
            perf_file.write(s.getvalue())
        return retval

    return wrapper

@profileit
def function_you_want_to_profile(...)
    ...

Я надеюсь, что это помогает кому-то...

Answer 4

Если вы поняли, как написать декоратор для cProfile, подумайте об использовании functools.wraps.

Простое добавление одной строки может значительно облегчить отладку декораторов. Без использования functools.wraps имя оформленной функции было бы "оберткой", а строка документа была бы потеряна.

Таким образом, улучшенная версия будет

import cProfile
import functools

def profileit(func):
    @functools.wraps(func)  # <-- Changes here.
    def wrapper(*args, **kwargs):
        datafn = func.__name__ + ".profile" # Name the data file sensibly
        prof = cProfile.Profile()
        retval = prof.runcall(func, *args, **kwargs)
        prof.dump_stats(datafn)
        return retval

    return wrapper

@profileit
def function_you_want_to_profile(...)
    ...

Answer 5

Вот декоратор с двумя параметрами: именем выходного файла профиля и полем для сортировки по результатам. Значением по умолчанию является совокупное время, которое полезно для поиска узких мест.

def profileit(prof_fname, sort_field='cumtime'):
    """
    Parameters
    ----------
    prof_fname
        profile output file name
    sort_field
        "calls"     : (((1,-1),              ), "call count"),
        "ncalls"    : (((1,-1),              ), "call count"),
        "cumtime"   : (((3,-1),              ), "cumulative time"),
        "cumulative": (((3,-1),              ), "cumulative time"),
        "file"      : (((4, 1),              ), "file name"),
        "filename"  : (((4, 1),              ), "file name"),
        "line"      : (((5, 1),              ), "line number"),
        "module"    : (((4, 1),              ), "file name"),
        "name"      : (((6, 1),              ), "function name"),
        "nfl"       : (((6, 1),(4, 1),(5, 1),), "name/file/line"),
        "pcalls"    : (((0,-1),              ), "primitive call count"),
        "stdname"   : (((7, 1),              ), "standard name"),
        "time"      : (((2,-1),              ), "internal time"),
        "tottime"   : (((2,-1),              ), "internal time"),
    Returns
    -------
    None

    """
    def actual_profileit(func):
        def wrapper(*args, **kwargs):
            prof = cProfile.Profile()
            retval = prof.runcall(func, *args, **kwargs)
            stat_fname = '{}.stat'.format(prof_fname)
            prof.dump_stats(prof_fname)
            print_profiler(prof_fname, stat_fname, sort_field)
            print('dump stat in {}'.format(stat_fname))
            return retval
        return wrapper
    return actual_profileit


def print_profiler(profile_input_fname, profile_output_fname, sort_field='cumtime'):
    import pstats
    with open(profile_output_fname, 'w') as f:
        stats = pstats.Stats(profile_input_fname, stream=f)
        stats.sort_stats(sort_field)
        stats.print_stats()