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.
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.info(...), depending on how important you think the output is. Anything below the level you specified in the config will be ignored.
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.
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.