I want to create a decorator that profiles a method and logs the result. How can this be done?
1
- What do you mean by "profiles"? Timing? Or locating code to optimize? If the latter, try this.Mike Dunlavey– Mike Dunlavey2011-03-21 13:28:36 +00:00Commented Mar 21, 2011 at 13:28
Add a comment |
6 Answers
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.
14 Comments
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.
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.
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'.)
|
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.
answered Mar 21, 2011 at 9:26
Ioan Alexandru Cucu
12.4k7 gold badges40 silver badges39 bronze badges
3 Comments
Iacks
Isn't this what was asked? He never asked anything about timing. He did ask about profiling.
pfctdayelise
Presumably import time, not timeit.
steveohmn
logging.info() does not get printed in the console @ioan-alexandru-cucuI 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...
1 Comment
Vapourisation
Thank you! I had something similar a while ago but lost the code, this is exactly what I needed.
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(...) ... Comments
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() 
Comments
According official docs https://docs.python.org/3/library/profile.html you can just use a Profile context manager something like this:
import cProfile from pstats import Stats, SortKey def profiler(func): def wrapper(*args, **kwargs): with cProfile.Profile() as pr: result = func(*args, **kwargs) Stats(pr).sort_stats(SortKey.TIME).print_stats(10) # sort by total execution time and limit output to 10 lines return result return wrapper @profiler def your_function(): # some actions 