Conditionally Logging Expensive Tasks

(I have shown this technique in my mailing list. If this kind of thing seems interesting, why not subscribe?)

Imagine you want to log something that is, potentially, expensive to calculate. For example, in DEBUG mode, you would like to count the classes of the objects in gc.get_objects() and log those counts: this is often a useful technique for diagnosing reference leaks. This is pretty heavy to calculate, and logging it always sounds wasteful.

The logging module has lazy interpolation.

A line like

logging.debug("total number: %r", 2500)

will not bother calculating the string interpolation total number: 2500 unless the logging level is set to output it.

However, calling logging.debug("total number: %r", get_object_counts()) will still call get_object_counts() regardless. It is not the cost of calculating the interpolation, but that of calculating the counts themselves that you would like to avoid.

One way to piggy-back on the lazy interpolation to do lazy evaluation is to write a custom class with a lazy __repr__():

class OnDemand:
    def __init__(self, callable):
        self.callable = callable
    def __repr__(self):
        return repr(self.callable())

This defines a class, OnDemand, which will only call the function when it needs its repr.

This allows us to write code like:

logging.debug("total number: %r", OnDemand(get_object_counts))`

Now, get_object_counts() will not be called at all: notice that the logging line does not call it. This makes the lazy evaluation explicit: we explicitly delay evaluation with OnDemand.

Here is a simple example of how it would work:

>>> def get_object_counts():
...     print("doing something expensive")
...     return 5
...
>>> debug_logging.debug("result is %r", OnDemand(get_object_counts))
doing something expensive
DEBUG:debug:result is 5
>>> warnonly_logging.debug("result is %r", OnDemand(get_object_counts))
>>> warnonly_logging.debug("result is %r", get_object_counts())
doing something expensive

Note that when the warnonly_logging is called with a .debug() method, the expensive calculation is not done: not only is the log message ignored, but the function that calculates the value is not done.

The last line shows that without the careful usage of OnDemand, the expensive calculation is done.

This should make it easy to sprinkle heavy calculations in logging.debug statements. Coupled with easy ways to trigger logging level changes (which are beyond the scope of this article) this gives a powerful way to get insight into your program's innards.

(Thanks to Adi Stav, Avy Faingezicht, Chris Withers, Dave Briccetti, and Lucas Wiman on their feedback on an early draft of this article. Any mistakes or issues that remain are my responsibility.)