Is it possible to do "extended" time monitoring in Python using a decorator?

Question

I have a simple set of functions that use each other. For example:

def func(x)
    y = func_1(x)
    z = func_2(y)
    return z

def func_1(x):
    return x + 1

def func_2(x)
    a = func_a(x)
    b = func_b(y)
    return b

As you can see, the func is the "root" function that uses func_1 and func_2 and func_2, in its turn, uses func_a and func_b. When I call func I get z as the result.

Now I would like to "modify" or "extend" my functions with a decorator such that in the end (as a result of func) I get not only z but also an object that shows me how much it took to execute this function as well as what functions have been used by the function and how long it took to execute these "sub-functions" as well as what "sub-sub-functions" have been used by what "sub-functions" and how long does it took to execute them. To make it simpler I give an example of what I expect as an "additional" result:

{
    'fname' : 'func',
    'etime' : 12.000,
    'subs'  : [
        {
        'fname' : 'func_1',
        'etime' : 2.000,
        'subs'  : []
        },
        {
        'fname' : 'func_2',
        'etime' : 10,
        'subs'  : [
            {
            'fname' : 'func_a',
            'etime' : 6,
            'subs' : []
            },
            {
            'fname' : 'func_b',
            'etime' : 4
            'subs' : []
            }
        ]
        }
    ]
}

In the above example "fname" means name of the function, "etime" means execution time (how long did it took to execute this function), and "subs" is a list of sub-function that were used by the considered function. For each sub-function we have the same keys ("fname", "etime", "subs"). So, it is a "recursive" structure. If a function did not use any function then "subs" maps to an empty list.

I have started with the following decorator:

def decorate(func):

    def wrapper(*args, **kw):

        d = {}
        d['fname'] = func.__name__
        t0 = time.time()

        out = func(*args, **kw)

        d['etime'] = time.time() - t0

        d['subs'] = ?

        ?.append(d)

    return wrapper

But then I stack with the further implementation. I cannot find a solution and am not even sure that it is possible.

The idea is that I use a decorator to extend the number of arguments passed to each function. Each function gets an empty list containing all sub-functions used so far and append itself to this list.

The decorator wraps around the function, it sees what it receives (arguments) and sends back (`return` values) but *not* what it calls. To do this with a decorator, you would have to wrap all functions involved with something that shared state across the different function calls. Alternatively, use an existing profiler. — jonrsharpe, Sep 03 '14 at 15:37
Not to say your question isn't legitimate, but you're pretty much reinventing the wheel here. The `@profile` decorator from the [`profilestats`](https://pypi.python.org/pypi/profilestats/) package does exactly this. Also see [this answer](http://stackoverflow.com/questions/19857749/what-is-the-reliable-method-to-find-most-time-consuming-part-of-the-code/19857889#19857889) for a usage example and some more details. — Lukas Graf, Sep 03 '14 at 15:39
@ jonrsharpe, I know. But if each function passes the same object from its argument to all its sub-functions and each sub-function writes something to this object then, in the decorator, after an execution of the wrapped function we get information written by the sub-functions. — Roman, Sep 03 '14 at 15:40
So you want one of the arguments to the function to actually be for its decorator? That seems messy, and means that a decorated function will have a different call signature to the undecorated version. Look into the existing options for profiling code before you commit to rolling your own. — jonrsharpe, Sep 03 '14 at 15:43
That seems completely counter to Python, if that's the case. You're better off passing arguments to the decorator directly. This tends to be the easiest to learn with class decorators, something like sebdestol's answer. — tsalaroth, Sep 07 '14 at 12:04

sebdelsol · Accepted Answer · 2014-09-08T15:31:34.823

You would be better using a real profiler as suggested.

Still, it can be done with a decorator class. You'll be able to keep track of the subs list with a stack shared between all the decorator's instances.

class profile(object):
    #class variable used as a stack of subs list
    stack = [[]] 

    def __init__(self, f):
        self.f = f

    def __call__(self, *args, **kw):
        func = dict(fname = self.f.__name__)

        #append the current function in the latest pushed subs list
        profile.stack[-1].append(func)

        #push a new subs list in the stack
        profile.stack.append([]) 

        #execution time of the actual call
        t0 = time.time()
        out = self.f(*args, **kw)
        func['etime'] = time.time() - t0

        #pull the subs list from the stack
        func['subs'] = profile.stack.pop()

        return out

    @classmethod
    def show(cls):
        import json #useful to prettify the ouput
        for func in cls.stack[0]:
            print json.dumps(func, sort_keys=True, indent=4)

You'll have to decorate all the functions you want to appear in the profile with @profile. Note that in a real world situation, you might want to handle exceptions when a decorated function fails.

Ouput:

profile.show() shows the list of all the called 'root' functions profiled with all their inners' calls.

{
    "etime": 4.5, 
    "fname": "func", 
    "subs": [
        {
            "etime": 1.0, 
            "fname": "func_1", 
            "subs": []
        }, 
        {
            "etime": 3.5, 
            "fname": "func_2", 
            "subs": [
                {
                    "etime": 1.5, 
                    "fname": "func_a", 
                    "subs": []
                }, 
                {
                    "etime": 2.0, 
                    "fname": "func_b", 
                    "subs": []
                }
            ]
        }
    ]
}

I think that's backwards. Isn't the function passed to __call__ and the args to __init__ when you're passing arguments to the decorator class? — tsalaroth, Sep 07 '14 at 12:03
Not when the decorator has no arguments, `__init__` is called when a function f is decorated and `__call__` each time f is called. — sebdelsol, Sep 07 '14 at 17:22
you probably went to use some `try/except` logic in case the function calls fail — acushner, Sep 08 '14 at 13:33
@acushner, you're right. I guess there's a lot of other ways it could fail. Yet that's not really the question. So I'd rather keep this code simple. — sebdelsol, Sep 08 '14 at 13:58

Is it possible to do "extended" time monitoring in Python using a decorator?

1 Answers1