Python logging and string formatting

May 03, 2020 • 2 min read

You open your latest pull request, only to be met with a pointless suggestion:

- logging.info(f"The thing is: {thing}")
+ logging.info("The thing is: %s", thing)

Why revert to the ancient % format when we have f-strings?

The question misses the subtler point. In the first case logging.info receives a single argument, the interpolated string f"The thing is: {thing}". Whereas in the second case it receives two arguments, the template string "The thing is: %s" and thing.

It's about efficiency.

logging is lazy with string interpolation to be efficient. If we pass in an already-interpolated string, we don't allow the logging module to make the decision as to when to compute the interpolation. If we pass the template and the objects to be rendered, the logging module can decide when to interpolate, if at all.

# Prefer this
logging.info("The thing is: %s", thing)
# Not this
logging.info(f"The thing is: {thing}")
logging.info("The thing is: {}".format(thing))
logging.info("The thing is %s" % thing)

This way, the string is only interpolated when the logger is actually required to emit a message, i.e., when the message level matches the configured logger level. For example, if we configure the root logger to the INFO level, none of the logger.debug message strings ever need to be interpolated.

Is string interpolation really that expensive?

When an interpolated string like f"The thing is: {thing}" is evaluated, the rendered object's thing.__str__ method is called. This is expected to be a cheap operation. But the cost can grow expensive for complex objects, or if repeated many times, say, inside deeply nested loops:

for foo in foos:
    for bar in bars:
        for baz in bazs:
            logger.debug(
                "foo: %s, bar: %s, baz: %s",
                foo,
                bar,
                baz
            )