Profiling a system with extensively reused decorators

Question

Our code base has a few decorators that are used extensively.

When I create a runtime profile, a large part of the call graph looks like an hour glass; many functions call one function (the decorator), which then calls many functions. This is a less-useful profile than I'd like.

Is there any way to rectify this situation? Removing the decorator is not an option; it provides necessary functionality.

We've considered manually stripping the decorator from the cProfile data after the fact, but it doesn't seem possible, because the data is summarized into caller->callee relationships, which destroys the caller->decorator->callee relationship.

Why isn't that useful? If the profiling information points towards the decorator, then any improvements to the decorator implementation could entail huge changes. — jcollado, Feb 21 '12 at 23:03
jcollado: because the decorator is a trivial part of the runtime, but it's callees are not. It masks what is the "true caller" of those callees, which may be a key piece of information in deciding how to optimize. — bukzor, Feb 21 '12 at 23:18

Amber · Accepted Answer · 2012-02-22T00:40:10.053

Using something like the new library (or types in Python 2.6+), you could theoretically dynamically create a code object and then a function object based on that code object that had a built-in name that varied along with the function you were wrapping.

That would allow you to manipulate things as deep as <func>.__code__.co_name (which is normally read-only).

import functools
import types

def metadec(func):

    @functools.wraps(func)
    def wrapper(*args, **kwargs):   
        # do stuff
        return func(*args, **kwargs)

    c = wrapper.func_code
    fname = "%s__%s" % (func.__name__, wrapper.__name__)

    code = types.CodeType(
                c.co_argcount, 
                c.co_nlocals,
                c.co_stacksize,
                c.co_flags,  
                c.co_code,        
                c.co_consts,         
                c.co_names,
                c.co_varnames,
                c.co_filename,
                fname, # change the name
                c.co_firstlineno,
                c.co_lnotab,
                c.co_freevars,
                c.co_cellvars,
            )

    return types.FunctionType(
            code, # Use our updated code object
            wrapper.func_globals,
            fname, # Use the updated name
            wrapper.func_defaults,
            wrapper.func_closure,
        )

(functools.wraps is still used here in order to allow for pass-through of things like docstrings, module names, etc.)

In [1]: from metadec import metadec

In [2]: @metadec
   ...: def foobar(x):
   ...:     print(x)
   ...:     
   ...:     

In [3]: foobar.__name__
Out[3]: 'foobar__wrapper'

In [4]: foobar(1)
1

score 5 · Answer 2 · edited Feb 22 '12 at 16:31

I'm going to guess that it's not the decorator itself that's cluttering up your profiling, but rather the wrapper function created by the decorator. And that's happening because all the wrapper functions have the same name. To address this, just have the decorator change the name of the wrapper function.

def decorator(func):

    def wrapper(*args):
        print "enter func", func.__name__
        return func(*args)

    wrapper.__name__ += "_" + func.__name__
    return wrapper

You could also use functools.wraps(), but then the name of the wrapper function will match the name of the function it's wrapping. I guess that would be OK for profiling.

Now, the function's code object also has a name. Python doesn't store references to functions on the stack, only to code objects, so if the profiler is getting the name of the wrapper function from a stack frame, it will get this name. Wrappers defined in the usual way share the code object (even though the function object is different) unless you explicitly rebuild the code object and the function object for each wrapper function. This is quite a bit more work and very CPython-specific (might even be version-specific). But here's how you might go about it:

from types import FunctionType, CodeType    

def decorator(func):

    def wrapper(*args):
        print "enter func", func.__name__
        return func(*args)

    name = wrapper.__name__ + "_" + func.__name__

    func_code = wrapper.func_code
    new_code  = CodeType(
            func_code.co_argcount, func_code.co_nlocals, func_code.co_stacksize,
            func_code.co_flags, func_code.co_code, func_code.co_consts,
            func_code.co_names, func_code.co_varnames, func_code.co_filename,
            name, func_code.co_firstlineno, func_code.co_lnotab,
            func_code.co_freevars, func_code.co_cellvars)
    wrapper   = FunctionType(
            new_code, wrapper.func_globals, name, wrapper.func_defaults,
            wrapper.func_closure)

    return wrapper

Both the function's name and the code object's name are set here to wrapper_originalfuncname and they should thus be counted separately from the wrapped function in the profiler. You could easily set them to just the original function's name so that their run time would be rolled in with the original function's instead.

Assuming the decorator were properly created with something like `functools.wraps()`, the `__name__` would already be getting set anyway. — Amber, Feb 21 '12 at 23:29
Embellished this answer since if the profiler's getting the function name from the stack frame, it's actually going to be the code object's name, not the function's. — kindall, Feb 22 '12 at 00:17
I updated mine as well (I had passed cellvars and freevars as kwargs by accident, when they're supposed to be posargs, which is what was making it segfault). I'm keeping `functools.wraps()` in there because that way things like `__module__`, `__doc__` etc get passed through as well. — Amber, Feb 22 '12 at 00:37
Given all of this information, how would you go about fixing this in the python stdlib? I can think of three possible ways: 1) Add a 'recreate_code' option to functools.wraps 2) Make cProfile inspect `__name__` instead of co_name 3) Change func.__name__ to a property which sets co_name to match. — bukzor, Feb 22 '12 at 16:29
I think the biggest problem is that the Python stack frames don't contain a reference to the function, only to the code object, and code objects are shared among functions anytime there's a closure. I would add a reference to the current function in the stack frame and have cProfile use that. — kindall, Feb 22 '12 at 17:42
Alternatively, having some way to tell `cProfile` that it should ignore certain stack frames when logging its caller/callee data could also be useful ("skip code blocks named like this pattern"). — Amber, Feb 22 '12 at 21:09

Profiling a system with extensively reused decorators

2 Answers2