A decorator that profiles a method call and logs the profiling result

Question

I want to create a decorator that profiles a method and logs the result. How can this be done?

Solution 1

The decorator would look something like:

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

Anyway, if you want to do some serious profiling I would suggest you use the profile or cProfile packages.

Solution 2

If you want proper profiling instead of timing, you can use an undocumented feature of cProfile (from this question):

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

If you want more control over the file name then you will need another layer of indirection:

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

It looks complicated, but if you follow it step by step (and note the difference in invoking the profiler) it should become clear.

Solution 3

I like the answer of @detly. But sometimes its a problem to use SnakeViz to view the result.

I made a slightly different version that writes the result as text to the same file:

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

I hope this helps someone...

Solution 4

If you've understood how to write a decorator for cProfile, consider using functools.wraps.

Simply adds one line can help you debugging decorators much easier. Without the use of functools.wraps, the name of the decorated function would have been 'wrapper', and the docstring of would have been lost.

So the improved version would be

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

Solution 5

Here is a decorator with two parameters, the profile output's file name, and the field to sort by the results. The default value is the cumulative time, which is useful to find bottlenecks.

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

View more solutions

Comments

[Mike Dunlavey]

What do you mean by "profiles"? Timing? Or locating code to optimize? If the latter, try this.

[Iacks]

Isn't this what was asked? He never asked anything about timing. He did ask about profiling.

[Iacks]

It's not very clear what some_variation_on is. I figured its a file as dump_stats takes a file? But it looks like a method.

[detly]

@lacks - it's just a hypothetical function that takes the name of the function and turns it into a filename, eg. func.__name__ + .profile. It doesn't have to be anything.

[Iacks]

You could make this clearer, as its calling a method outside the scope that could be anything and its not even clear that its going to be a filename until you actually know what its doing! Putting a string here or a comment explaining would be alot more helpful!

[Iacks]

Ahh much better! I am using it now!

[beardc]

How do you read the .profile file? It doesn't appear to be text.

[beardc]

Nevermind, I think you just do pr = pstats.Stats(filename) and then play around with the pr object.

[detly]

@BirdJaguarIV - it can only be loaded by one of the profiling modules, but I use RunSnakeRun.

[kynan]

Here's a variant of this decorator with a few configuration options for the output that's printed: sorting, number of lines printed, stripping directories

[emispowder]

I like using a combination of this answer with the example from docs.python.org/2/library/profile.html#profile.Profile to print to stdout instead of writing to file.

[Eligio Mariño]

Presumably import time, not timeit.

[madjardi]

gprof2dot.py -f pstats profile_for_func1_001 | dot -Tpng -o profile.png see in here

[Cecil Curry]

The canonical means of visualizing profile files as of 2016 is SnakeViz, the Python 3-compatible successor to RunSnakeRun. (You know... just sayin'.)

[dogewang]

if my func is wraped by a tornado coroutine,where should i put this decoratoe

[Felipe Ferri]

This decorator is extraodrinarily useful. Combined with SnakeViz then...

[Thomas Pegler]

Thank you! I had something similar a while ago but lost the code, this is exactly what I needed.

[BetterCallMe]

Don't remove return retval statement from this code. I removed and It costed me 3 days of headache until I figured out that my damn method was returning None all the time due to this smart dumbness.

[steveohmn]

logging.info() does not get printed in the console @ioan-alexandru-cucu