19

Python logging: why printf-style string formatting may be better thanf-strings

 4 years ago
source link: https://blog.pilosus.org/posts/2020/01/24/python-f-strings-in-logging/
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.

Python provides more than one way to format strings: %-formatting , str.format() , string.Template and f-strings . What format developers use is the matter of personal aesthetic reasons rather than anything else. Still there are use cases where good old printf-style %-formatting may have advantages over other formats. Python’s logging module is one of these cases. Let’s see what are the main reasons to use %-formatting for logging in Python.

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 . Arguments 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.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 message is not logged as root logger’s level is higher than debug . That’s why that message is not formatted. In step 4 f-string is evaluated even though it’s not getting logged either.

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.


About Joyk


Aggregate valuable and interesting links.
Joyk means Joy of geeK