4 years ago

A Tornado decorator for timing critical functions

Recently I have been working on a small pet project using the great asynchronous networking library Tornado. This project communicates with various other APIs and systems such as MySQL, Amazon SQS etc. I was keen to just have a rough idea how long my application was spending using these systems. I didn't really want to go to all the effort of either doing some application profiling, or modifying my application to add loads of timing/logging code.

I thought creating a python decorator to do the task would be the easiest/quickest. The code below creates a decorator that will record the amount of time a method takes and print the time to standard stdout.

def log_runtime(method):
    def wrap(*a, **k):
        arg_spec = inspect.getargspec(method)
        classname = ""
        if 'self' in arg_spec.args:
            classname = a[0].__class__.__name__
        start_time = time.time()
        retval = method(*a, **k)
        finish_time = time.time()
        timestr = datetime.datetime.now().strftime("%Y-%m-%d %H:%M:%S.%f")
        print "%s : %s" % (timestr,
                           "%s.%s() took %s secs." % (classname,
                                                 finish_time - start_time))
        return retval
    return wrap

The decorator will take any method/function regardless of its parameters and wrap timing and logging logic around it.

Lets take the following code

class democlass:
    def function_that_we_want_to_time:
        print "function_that_we_want_to_time() complete."

We can modify this to use our timing decorator in the following way.

class democlass:
    def function_that_we_want_to_time:
        print "function_that_we_want_to_time() complete."

Then when the function_that_we_want_to_time() method is called a message will be printed on stdout that looks like

2013-06-12 12:50:14:282084 : democlass.function_that_we_want_to_time() took 0.23882317543 secs.
function_that_we_want_to_time() complete.