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.

Answer 1

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

Answer 2

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.