Ein Dekorator, der einen Methodenaufruf profiliert und das Ergebnis der Profilierung protokolliert

Question

Ich möchte einen Dekorator erstellen, der ein Methodenprofil erstellt und das Ergebnis protokolliert. Wie kann das gemacht werden?

Answer 1

Wenn Sie anstelle des Timings ein ordentliches Profiling wünschen, können Sie eine undokumentierte Funktion von cProfile (aus 本問 ):

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(...)
    ...

Wenn Sie mehr Kontrolle über den Dateinamen haben möchten, benötigen Sie eine weitere Ebene der Umleitung:

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(...)
    ...

Es sieht kompliziert aus, aber wenn Sie Schritt für Schritt vorgehen (und den Unterschied beim Aufrufen des Profilers beachten), sollte es klar werden.

Answer 2

Der Dekorateur würde etwa so aussehen:

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

Wie auch immer, wenn Sie ein ernsthaftes Profiling durchführen wollen, würde ich Ihnen empfehlen, die Pakete profile oder cProfile zu verwenden.

Answer 3

Mir gefällt die Antwort von @detly. Aber manchmal ist es ein Problem zu verwenden SnakeViz um das Ergebnis zu sehen.

Ich habe eine etwas andere Version erstellt, die das Ergebnis als Text in dieselbe Datei schreibt:

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(...)
    ...

Ich hoffe, das hilft jemandem...

Answer 4

Wenn Sie verstanden haben, wie man einen Dekorator für cProfile schreibt, sollten Sie die Verwendung von functools.wraps .

Das einfache Hinzufügen einer Zeile kann die Fehlersuche bei Dekoratoren erheblich erleichtern. Ohne die Verwendung von functools.wraps wäre der Name der dekorierten Funktion "wrapper" gewesen und der docstring von wäre verloren gegangen.

Die verbesserte Version würde also lauten

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

Hier ist ein Dekorator mit zwei Parametern, dem Dateinamen der Profilausgabe und dem Feld, nach dem die Ergebnisse sortiert werden sollen. Der Standardwert ist die kumulierte Zeit, die nützlich ist, um Engpässe zu finden.

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()