Python: wrap all functions in a library

Question

We use a library provided by another internal team. (Shaky analogy starts now)

from externalTeam import dataCreator
datacreator.createPizza()
datacreator.createBurger()
datacreator.createHotDog()

Recently we found a single method of theirs was taking over a minute to execute in certain situations. To debug this, I had to go into our code and add timeouts around every call of this method.

import time
from externalTeam import dataCreator
start = time.clock()
datacreator.createPizza()
stop = time.clock()
print "It took %s seconds to perform createPizza" % (str(stop-start))

In hindsight, that's because we're calling createPizza all over the place, and we don't control createPizza itself (the analogy is starting to break down a little here). I'd rather just call createPizza in one place, and be able to add a timer around that. My first thought to accomplish this would be to create a wrap all their methods in my own wrapper class. That's the opposite of DRY though, and anytime they add another method I'd have to update our library to wrap that as well:

import time
from externalTeam import dataCreator
def createPizza(self):
    start = time.clock()
    datacreator.createPizza()
    stop = time.clock()
    print "It took %s seconds to perform createPizza" % (str(stop-start))

def createBurger(self):
    start = time.clock()
    datacreator.createPizza()
    stop = time.clock()
    print "It took %s seconds to perform createBurger" % (str(stop-start))

def createHotDog(self):
    start = time.clock()
    datacreator.createPizza()
    stop = time.clock()
    print "It took %s seconds to perform createHotDog" % (str(stop-start))    

What I want is a way to always execute a few lines of code around every function that's being called from dataCreator. There must be some way to do that through an intermediate class whose methods can be dynamically defined - or rather left undefined, right?

Giulio

are we talking about functions or classes with methods? – Paradrop

I know about decorators. What do I decorate though? createPizza and createBurger are functions on their side. – Giulio

@jollybox.de - we're talking about classes with methods. – Giulio

"That's the opposite of DRY though". Not really. You're wrapping, not repeating. And yes, your Facade will grow as the underlying library goes. That's okay. – Gyimah

Answer 1

I would create a dataCreator adapter class that would work like this:

1. Have a methods2wrap list of the methods from dataCreator that needs to be wrapped into the debugging/timing functionality.
2. Have an overridden __getattribute__() that would map 1:1 onto the dataCreator methods, wrapping the methods in methods2wrap into a timing debug message.

Proof-of-concept code (the example wrap the class list and insert a debugging timestamp around its method append).

import time

class wrapper(list):

    def __getattribute__(self, name):
        TO_OVERRIDE = ['append']
        if name in TO_OVERRIDE:
            start = time.clock()
        ret = super(list, self).__getattribute__(name)
        if name in TO_OVERRIDE:
            stop = time.clock()
            print "It took %s seconds to perform %s" % (str(stop-start), name)
        return ret

profiled_list = wrapper('abc')
print profiled_list
profiled_list.append('d')
print profiled_list
profiled_list.pop()
print profiled_list

Of course you could build on this example and make it parametric, so that at initialisation time you can set what class to wrap and what methods should be timed...

EDIT: Note that TO_OVERRIDE is reassigned at each __getattribute__ call. This is by design. If you you would make it as a class attribute, __getattribute__ would recursively loop (you should use an explicit call to the parent __getattribute__ method to retrieve it, but this would probably be slower than simply rebuild the list from scratch.

HTH

Renz

This doesn't seem to handle the execution time inside the method that is returned. In this solution, profiled_list.append('d') will only include the time it took to retrieve the append method, not the time to actually append. I think it might be necessary to return a wrapped version of the method as well. – Balladeer

Answer 2

If you're trying to profile Python code, you should use Python's built-in profiling libraries instead of trying to do it manually.

Cay

I mostly want to profile their one library's calls, and output to our log on the debug level. Seems like a profiling library might be able to do that, so I'll look into that link, thanks! – Giulio

Answer 3

Why not a single wrapper function which just calls its argument?

def wrapper(func, *args, **kwargs):
    ... timing logic ...
    response = func(*args, **kwargs)
    ... more timing logic
    return response

and call it:

wrapper(datacreator.createPizza, arg1, arg2, kwarg1=kwarg)

note you pass the function itself, but without calling it.

Stigmasterol

Like a decorator, right? This would work, but I'd have to write one line of code like wrapper(datacreator.createPizza, arg1, arg2, kwarg1=kwarg) for every function from their library that I call. Whenever they introduce new functionality I have to add another line... I'm wondering if there's a way to avoid that. – Giulio

@caribou - not quite - a Python decorator returns a function object. But it's trivial to turn this into a decorator. – Beestings

@caribou - You did not comment on my answer, but that's the problem my solution tries to go around. Of course you still have to specify which methods you want to time, but their name will be all you have to insert.... or did I miss anything? – Renz

Answer 4

The following template could help:

class MeteredClient(Client):
  def __init__(self, *args, **kwargs):
    super(MeteredClient, self).__init__(*args, **kwargs)

  def __getattribute__(self, method_name):
    attribute = super(Client, self).__getattribute__(method_name)

    if not inspect.ismethod(attribute):
      return attribute

    metric = TIMINGS.labels(method_name)

    def decorator(*args, **kw):
      start_time = get_time()
      rv = attribute(*args, **kw)
      metric.observe(get_time() - start_time)
      return rv

    return decorator

Recently

How could it help? Can you give some extra explanation? – Babel