Decorators

Tags: Python, Software Engineering, Intermediate Python

I love decorators. Python is a pretty concise language but all too often you can end up with cluttered code that is full of monitoring and debugging logic. Let’s take some pretty typical code and see if we can improve it with some decorators.

This post uses timing as a contrived example, in the real world you’ll probably just want to using a pre-existing timing decorator and be done with it. Realistically you’ll find decorators useful for things like authentication, metrics, logging, tracing and really anything where you want to do something before or after a callable.

import logging
import time

log = logging.getLogger(__name__)


def fetch_something_to_start():
    ...

def process_our_data(data):
    ...

def deliver_results(results):
    ...


if __name__ == '__main__':
    logging.basicConfig()

    start_time = time.perf_counter()
    data = fetch_something_to_start()
    log.info('Fetch took %r', time.perf_counter() - start_time)

    start_time = time.perf_counter()
    results = process_our_data(data)
    log.info('Process took %r', time.perf_counter() - start_time)

    start_time = time.perf_counter()
    deliver_results(results)
    log.info('Delivery took %r', time.perf_counter() - start_time)

There’s nothing especially wrong with and it’s no real cardinal sin. It does however clutter things and make them hard to read. In the eternal words of Raymond Hettinger, there must be a better way…

Decorators work as syntactic sugar on functions. They provide a convenient and compact shortcut to wrapping one function (or callable really) with another function call.

def function():
    pass
bar = foo(bar)

# is equivalent to...
@foo
def bar():
    pass

With that in mind we can write a decorator and clean up our example code.

import logging
from time import perf_counter
from functools import wraps


log = logging.getLogger(__name__)


def timer(function):

    # We use functools.wraps here to make sure our function signatures
    # stay intact.  We do this so function.__name__ and
    # function.__doc__ show the wrapped function details rather
    # than our decorators.
    @wraps(function)
    def wrapper(*args, **kwargs):
        # Mark our start time.
        start = perf_counter()
        # Get our results
        result = function(*args, **kwargs)

        # Log out the details for later analysis
        log.debug(
            '%s elapsed time: %r',
            # Inspect the function name.
            function.__name__,
            # Calculate the elapsed time
            perf_counter() - start
        )
        return result
    return wrapper

We’re timing our function calls using the perf_counter clock and logging the results 1 inside the decorator. The decorator inspects the wrapped functions name and uses that in it’s output.

This can be saved to a file ‘utils.py’ in the same directory as our code.

With this in mind the code at the start of the article can be simplified now.

import logging
import time

# Import our timer from utils.py
from utils import timer

log = logging.getLogger(__name__)


@timer
def fetch_something_to_start():
    ...

@timer
def process_our_data(data):
    ...

@timer
def deliver_results(results):
    ...


if __name__ == '__main__':
    logging.basicConfig()

    data = fetch_something_to_start()
    results = process_our_data(data)
    deliver_results(results)

As you can see it’s much easier to pick out the important logic, all of the supporting code dissolves into the background.

Sometimes you’ll want to pass in data to your decorator to customise it. Given the way they work you can’t just call the function and pass arguments to it, you need to add another level.

# Say we want to do...
@timer(important=True)
def function():
    pass

# This expands to...
def function():
    pass
function = timer(important=True)(function)
# This would raise...
# TypeError: timer() got an unexpected keyword argument 'extra'

So making a few changes…

def timer(important=True):
    def _wrapper(f):
        @wraps(function)
        def wrapper(*args, **kwargs):
            # Mark our start time.
            start = perf_counter()
            # Get our results
            result = function(*args, **kwargs)

            # Log out the details for later analysis
            log.debug(
                '%s elapsed time: %r',
                # Inspect the functions name.
                function.__name__,
                # Calculate the elapsed time
                perf_counter() - start,
                # Log out our extra value.
                extras={"important": important}
            )
            return result
        return wrapper
    return _wrapper

We can then access our important keyword argument from inside the function. Keep in mind that arguments and keyword arguments are parsed and resolved at module import time. Any logic you put in the arguments will only be called once when the module is imported. This is the same reason you don’t use mutable data structures like lists as keyword arguments.

Hopefully this highlights some good use cases for decorators and some fun things you can do with them.

  1. Quick note here, don’t use time.time for measuring performance, it uses the gettimeofday syscall which can drift due to NTP. The perf_counter function is monotonic and only goes forwards, it also by default comes from the highest resolution clock which is a nice bonus. ↩︎