Python logging should use deferred formatting

[LukeShu]

Right now, there are lots of log statements that use f-strings or % expressions that ~expensively evaluate, just to be discarded by the logger because of the log level. At one point someone benchmarked that and figured out that we'd get substantial gains from wrapping a bunch of those in calls to logger.isEnabledFor(level). Well, that's not necessary; the logger can do that for us, if we let it defer the formatting to the logger.

@haq204 wrote:

just to add even more the needless complexity to python logging, f-strings squash things to a single string that gets added to the Log record so usually prefer to use old-school %s because the logging library is optimized to defer formatting until it needs to print it out with that format though you can change the Formatter on your logger instance.

It's also relevant when you use error log aggregators like Sentry for cleaner error log groupings if they are smart enough to deal with the actual log objects and not the message string

Relevant references:

• https://docs.python.org/3/howto/logging-cookbook.html#formatting-styles
• https://docs.python.org/3/howto/logging.html#optimization

TLDR: python logging is complicated

@LukeShu wrote:

@haq204 So the lesson isn't "go back to using old-school log("fmt" % args)", it's "use old-school-style 'fmt' with log("fmt", args)". Good to know.

Is there a linter that can check for formatted strings (f-strings, or % expressions) being passed to the logger, instead of passing the args as args?

And, FWIW, I wouldn't say that's complicated, it's a totally expected optimization (we do it in dlog!), just one that apparently none of us realized Python makes available to us.

It looks like this is what PyLint W1202 is checking for. We should start running PyLint.

[kflynn]

At one point someone benchmarked that...

That would be me. 🙂 And the self.debug or self._log_debug shortcut was about typing fewer characters, and about not constantly making the function call for logger.isEnabledFor(level).

If you look at the history, you'll see more than a few places where I later undid that wrapper in favor of the old-school "%s", arg-style logging... but yeah, it was never worth finding them all, and there are still places where the wrapper is better just because there's so much logging we want to do in debug mode.

All that said, though: yeah. We should run PyLint.