J2 Labs

Logging Function Calls with Decorators

I am one of those coders that tends to write verbose log output. Especially during early development stages of a system when you’re not sure your code is correct yet.

Python’s logging module leaves some things to be desired, but it’s an excellent default offering. Especially when used in a higher-order manner, like with a Python Decorator.

Logging

Starting a log can be two lines of code.

import logging
logging.basicConfig(level=logging.DEBUG, filename='whatevz.log')

From there, you call a function like logging.debug(...) or logging.info(...), depending on how important you think the output is. Anything below the level you specified in the config will be ignored.

• logging module

Checking Runtime With A Decorator

Decorators are handy tools. I can easily wrap some logging around a function without changing with how a coder uses that function.

Here is a simple decorator to log how long it takes a function to run. This function could be more robust, but I kept it simple for the example’s simplicity.

def log_runtime(method):
    def wrapper(*a, **kw):

        start = time.time()
        retval = method(*a, **kw)
        finish = time.time()

        logging.debug('%s took %s seconds to run' % (method.__name__,
                                                     (finish - start)))
        return retval
    return wrapper

So before calling method we check the time. Then we call method and check the time again and print the difference to the log.

• What is a Python Decorator?

Using it then looks like this.

@log_runtime
def foo():
    print 'foo'

You’ll have a line in your log that looks like this, after foo has been called.

DEBUG:root:foo took 2.38418579102e-05 seconds to run

Try running it and look for a whatevz.log in the same directory as the code.

• Complete Code