Python logging optimization: format string until it cannot be avoided

Python logging methods like debug get in message argument along with optional args and kwargs. Args used for message formatting. Formatting of these arguments is deferred until it cannot be avoided. That means the final message is not evaluated if its log level is below the logger’s log level. On the other hand, f-string is really an expression that evaluated at runtime and it lacks logging’s optimizations. Let’s see an example:

In [1]: import logging
   ...: logging.basicConfig(level=logging.INFO)
   ...: logger = logging.getLogger('TestLogger')

In [2]: class A:
   ...:     def __str__(self):
   ...:         print('Unnecessary slow computations are done here!')
   ...:         return self.__class__.__name__
   ...:
   ...: obj = A()

In [3]: logger.debug("log level below INFO with args: %s", obj)

In [4]: logger.debug(f"log level below INFO with f-string: {obj}")
Unnecessary slow computations are done here!

In [5]: logger.debug("log level below INFO with args: %s" % obj)
Unnecessary slow computations are done here!

In [6]: logger.info("log level INFO with args: %s", obj)
Unnecessary slow computations are done here!
INFO:TestLogger:log level INFO with args: A

As you can see in step 3 a message doesn’t get logged as the root logger’s level is higher than debug. Logging module’s inner optimization makes sure that the message is not formatted in this case. Compare this to step 6.

In step 4 the f-string is also not logged because of the low log level. But it’s formatted anyway. That’s why you see obj.__str__ called.

Please note, that logging optimization doesn’t work for "format string" % values format. You can see that in step 5. The magic applies for %-format message if and only if the values for message formatting are passed in as logger method’s arguments!

So step 3 shows the optimized way to do message formatting in logging.

By the way, logging module has other nice optimizations that worth learning.

Sentry integration with logging

Sentry is a popular error tracking solution. Sentry integrates with the Python logging module. Error aggregation is another great feature of Sentry. Sentry looks at the event’s stacktrace, exception, or message and group it with existing ones if they are the same. If you get a hundred of exceptions that are all the same they get grouped into one with nice statistics.

When integrating Sentry with Python logging, it’s important to use %-formatting, so that Sentry can group your messages. As an example, let’s log failed attempts to retrieve an URL:

logger.error("Failed to retrieve URL %s", url)

With printf-style formatting your messages will be grouped together no matter what value url variable holds. But in this case:

logger.error(f"Failed to retrieve URL {url}")

you get a separate event in Sentry for every single unique URL. If you get 1000 unique URL, your Sentry dashboard might get messy.

Conclusions

Although Python is not Perl, there’s still more than one way to do it. Which string formatting style to use is an open question. Your project may not use Sentry, or you may prefer f-strings for readability reasons. You may see deferred formatting in logging for printf-style strings as a futile micro-optimization that won’t improve your app performance. But still, there may be cases where using an oldie but goldie %-formatting is beneficial, even at price of string formatting inconsistency.

Updates

2020-01-24 21:35. Many thanks to symmitchry who stressed out the importance of passing values for a message to be formatted as arguments to logger’s method (e.g. args to logger.debug()). Probably, that wasn’t quite clear in the first edition of the post. I’ve made this point explicit.

2020-01-25 13:45. As a redditor pointed out in the post discussion a Python linter pylint has a rule W1202 that warns you when str.format is used in logging. It’s worth to mention a rule W1201 too, which is triggered for the cases like in step 5 (see the code snippet above).