Determine origin of call in cProfile when wrapping a function's call method

Question

I have a C++ library that I am wrapping and exposing via python. For various reasons I need to overload the __call__ of the functions when exposing them via python.

A minimal example is below using time.sleep to mimic functions with various compute times

import sys
import time

class Wrap_Func(object):
    def __init__(self, func, name):
        self.name = name
        self.func = func

    def __call__(self, *args, **kwargs):
        # do stuff
        return self.func(*args, **kwargs)

def wrap_funcs():
    thismodule = sys.modules[__name__]

    for i in range(3):
        fname = 'example{}'.format(i)
        setattr(thismodule, fname, Wrap_Func(lambda: time.sleep(i), fname))

wrap_funcs()

When profiling my code via cProfile I get a list of __call__ routines. I am unable to ascertain which routines are taking the majority of the compute time.

>>> import cProfile
>>> cProfile.runctx('example0(); example1(); example2()', globals(), locals())
         11 function calls in 6.000 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        3    0.000    0.000    6.000    2.000 <ipython-input-48-e8126c5f6ea3>:11(__call__)
        3    0.000    0.000    6.000    2.000 <ipython-input-48-e8126c5f6ea3>:20(<lambda>)
        1    0.000    0.000    6.000    6.000 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        3    6.000    2.000    6.000    2.000 {time.sleep}

Expected

By manually defining the functions (this needs to be dynamic and wrapper as above) as

def example0():
    time.sleep(0)

def example1():
    time.sleep(1)

def example2():
    time.sleep(2)

I get the expected output of

>>> import cProfile
>>> cProfile.runctx('example0(); example1(); example2()', globals(), locals())
     11 function calls in 6.000 seconds
             8 function calls in 3.000 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 <ipython-input-58-688d247cb941>:1(example0)
        1    0.000    0.000    0.999    0.999 <ipython-input-58-688d247cb941>:4(example1)
        1    0.000    0.000    2.000    2.000 <ipython-input-58-688d247cb941>:7(example2)
        1    0.000    0.000    3.000    3.000 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        3    3.000    1.000    3.000    1.000 {time.sleep}

Note [this](https://stackoverflow.com/a/4492582/4013571) won't work as it needs to be able to be called generically — Alexander McFarlane, Aug 07 '18 at 18:40
Looking at the [`cProfile.Profiler.snapshot_stats`](https://github.com/enthought/Python-2.7.3/blob/master/Lib/cProfile.py#L111) it appears as though the root of the problem is the `__call__.func_code.co_name` — Alexander McFarlane, Aug 08 '18 at 15:38
related: https://stackoverflow.com/questions/40661758/name-of-a-python-function-in-a-stack-trace, https://stackoverflow.com/a/29488561/4013571 — Alexander McFarlane, Aug 08 '18 at 15:46

Alexander McFarlane · Answer 1 · 2019-08-28T10:03:24.773

The following combines answers from @alex-martelli to resolve patching the special __call__ method and @martijn-pieters to solve the problem of properly renaming a function code object

Edit: Since PEP 570 there is a new second argument to types.CodeType of code.co_kwonlyargcount. Remove this argument for earlier versions of Python.

import types

def rename_code_object(func, new_name):
    code = func.__code__
    return types.FunctionType(
        types.CodeType(
            code.co_argcount, 
            code.co_kwonlyargcount,  # comment out this line for earlier versions of python
            code.co_nlocals,
            code.co_stacksize, code.co_flags,
            code.co_code, code.co_consts,
            code.co_names, code.co_varnames,
            code.co_filename, new_name,
            code.co_firstlineno, code.co_lnotab,
            code.co_freevars, code.co_cellvars),
        func.__globals__, new_name, func.__defaults__, func.__closure__)

class ProperlyWrapFunc(Wrap_Func):

    def __init__(self, func, name):
        super(ProperlyWrapFunc, self).__init__(func, name)
        renamed = rename_code_object(super(ProperlyWrapFunc, self).__call__, name)
        self.__class__ = type(name, (ProperlyWrapFunc,), {'__call__': renamed})

After calling a modifying wrap_funcs() that uses the new class we get the expected output. This should also be compatible with exception tracebacks

>>> import cProfile
>>> cProfile.runctx('example0(); example1(); example2()', globals(), locals())
         11 function calls in 6.000 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    2.000    2.000 <ipython-input-1-96920f80be1c>:9(example0)
        1    0.000    0.000    2.000    2.000 <ipython-input-1-96920f80be1c>:9(example1)
        1    0.000    0.000    2.000    2.000 <ipython-input-1-96920f80be1c>:9(example2)
        3    0.000    0.000    6.000    2.000 <ipython-input-9-ed938f395cb4>:30(<lambda>)
        1    0.000    0.000    6.000    6.000 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        3    6.000    2.000    6.000    2.000 {time.sleep}

An aside: The call `type(name, (ProperlyWrapFunc,), {'__call__': renamed})` will need to be extended to include any other methods in the base class. Also, any special methods or `property` types will need to be declared separately — Alexander McFarlane, Aug 13 '18 at 14:00

Determine origin of __call__ in cProfile when wrapping a function's __call__ method

Expected

1 Answers1

Determine origin of call in cProfile when wrapping a function's call method