On Lazy Logging Evaluation
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 messages 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.
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 collections import UserDict
from functools import partial
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 the 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.
-
This is not a typical use of
partial
, but is a perfectly fine way of using the function. ↩︎