# On Lazy Logging Evaluation

Written by Taro Sato on . Tagged: Python

The stdlib logging package in Python encourages the C-style message format string and passing variables as arguments to its log method. For example,

logging.debug("Result x = %d, y = %d" % (x, y))  # Bad
logging.debug("Result x = %d, y = %d", x, y)     # Good

or

logging.debug("Result x = %(x)d, y = %(y)d" % {"x": x, "y": y})  # Bad
logging.debug("Result x = %(x)d, y = %(y)d", {"x": x, "y": y})   # Good

As the message does not need to be formatted when the logging level is set higher than the value set for the logger, we would waste time formatting the string in the “bad” cases above, when the message does not get logged at all. The “good” cases avoid this by deferring formatting until the logger finds it necessary.

Sometimes, though, we may want to log debug message with values that are expensive to compute. For example, in the above example, what if y depends on x, and the function that does the computation, e.g.,

def get_y(x):
... expensive computation ...
return result

is rather expensive? If this is done only for the purpose of the debug message, that would be a wasteful computation when the logging level is higher than the value at which the result is logged at.

## Lazy Function Evaluation with logging

Fortunately, it is easy to add lazy evaluation of function using a custom dict and functools.partial.

import logging
from functools import partial

from collections import UserDict

class Args(UserDict):
def __getitem__(self, key):
value = super().__getitem__(key)
if callable(value):
value = value()
return value

def get_y(x):
... expensive computation ...
return result

logging.debug("Result x = %(x)d, y = %(y)d", Args(x=x, y=partial(get_y, x)))

The idea is to use partial to defer the execution of function,1 and store it in a dict-like object that is aware of the need to call the function on access through the key.

1. This is not a typical use of partial, but is a perfectly fine way of using the function.

[return]