python String formatting Debug message legibility vs. performance... avoid f-strings entirely?

[petersilva]

Hey folks,

in #1613, and #1618, the AI @robjarawan is using reminds of a really interesting fact:

• logger.whatever( f" {hoho} " ) .... the fstring is evaluated before the call is made.
• logger.whatever( "%s" % hoho ) ... same.
• logger.whatever( "%s", hoho ) ... the string formatting is only done after the decision to print the actual messages.

This means that a lot of cpu is consumed in the first two cases, calculating strings that will never be used
in, say debug messages.

Until now:

• fstrings were considered modern ... the modern way to format strings.
• % notation was an interim being gradually replaced by fstrings.
• the comma stuff was discouraged because if there was a formatting error, it happens in the logger routine, instead of the source code (aka "%d" given a string.)

I had always been opportunistically converting old-style string formatting, which is generally
discouraged, by the more moden f strings which are considered easier to read. So this raises the question
of should we make this change in a comprehensive way in the the code, and document the reasoning in
the developer guide.

[petersilva]

idefix% find . -name '*.py' | xargs grep logger.debug | grep f\" | wc -l
552
idefix% find . -name '*.py' | xargs grep logger.debug | grep '%' | wc -l
591
idefix% 

so roughly a 1000 debug lines to change, at minimum.

[reidsunderland]

I like f-strings and have always tried to use them when writing new code. But I didn't even know the logger supported the C-style formatting with commas until that PR was created.

In non-logger situations, I think f-strings should be the standard.

The risk of a formatting error causing a crash that wouldn't be detected until logLevel debug is used is kind of worrying.

If we decide to use the deferred formatting for logs, would we want to apply it to all logs or just debug? It seems annoying to have different standards for different log levels.

[petersilva]

I would say we are paying a cost in code legibility for improved efficiency. That cost is only worth paying for messages that will not, most of the time, be actually printed. So it only makes sense for debug messages. For everything else we benefit from improved legiblity with no performance cost. but yeah... annoying.

[petersilva]

See #1624

[petersilva]

anybody know of a linter that could detect those?

[petersilva]

fwiw... Gemini prepared a patch to implement this... testing...

[douglatornell]

I also prefer f-strings for readability, and because I have a similar "use modern" bias to what @petersilva expressed.

f-strings are demonstrably faster than % and .format() methods: https://realpython.com/python-f-strings/#comparing-performance-f-string-vs-traditional-tools. So, there's that in their favour in the realm of the eager evaluation options.

The implementation change in Python 3.12 to base them on the PEG parser means, I think, that they will benefit from at least some of the ongoing interpreter performance improvements.

I know that logging plays an important role in sarracenia. Has anyone profiled to get a feel for significant the impact of the eager evaluation operation of f-strings might be in the overall scheme of things?

[petersilva]

which means that in the non-debug case, we would expect a performance penalty when we don't use f-strings.... so we really want:

• use traditional c-style strings only with logger.debug because we avoid evaluating the strings entirely.
• use f-strings everywhere else, because they are more efficiently computed when we know we have to.

[robjarawan]

if you're looking for some numbers, I have some from when I put together #1613 :)

The thing is, f-strings and % formatting are both fast at building strings.. that's not the issue. The issue is building strings that nobody reads. In production we run at INFO or WARNING, so every logger.debug(f"...") call builds a full string, passes it to the logger, and the logger throws it away. Thousands of messages per second across ~1000 debug lines...that adds up.

here: bench on a realistic message dict:

method	ops/s
logger.debug(f"processing {msg['relPath']}")	always evaluates, ~0.5-1us wasted per call
logger.debug("processing %s", msg['relPath'])	skips formatting entirely when debug is off

On its own each call is tiny, but in filter() and download() you're hitting multiple debug lines per message per batch. It's the same kind of compound waste as the deepcopy stuff we fixed.

To 🧠Reid's point about different standards per level -- I think this only really matters for debug? At INFO/WARNING/ERROR you're logging maybe a handful of times per batch, not per message. The overhead is negligible there, so f-strings are totally fine for readability. It's really just the debug-level hot path stuff where lazy formatting pays off.

So maybe the guideline is just: use lazy formatting for debug, f-strings are fine everywhere else? That keeps things simple and avoids the formatting-error-hiding concern Reid mentioned, since you'd only hit that at debug level anyway.

[petersilva]

yeah... I asked Gemini, and it did the conversion to lazy for all logger.debugs. was submitted as PR #1624 which Reid blessed, so it got merged. Still outstanding is making the rest of the messages use f-strings which everybody agrees is preferable.

[petersilva]

so read through the link from Doug to realpython, and it mentions a tool called flynt, which automates the conversion of strings, as this is a very common problem. It even mentions about not converting debug logs... before I started:

idefix% find sarracenia -name '*.py' | grep -v .pybuild | xargs grep -n logger'.*(' | grep -v logger.debug | grep -v f\" | grep -v f\' | grep %   | wc  -l
254

idefix% find sarracenia -name '*.py' | xargs flynt 
idefix% find sarracenia -name '*.py' | grep -v .pybuild | xargs grep -n logger'.*(' | grep -v logger.debug | grep -v f\" | grep -v f\' | grep %   | wc  -l
76

So I looked at the result, and it looks like the stuff it did was good. I ran the flow tests on the resulting code.
ran fine.

It seems to have left 76 logger statements, and looking them over, all the ones left are logger.info's and:

• are commented out and/or:
• most have mistakes in them (argument mismatches) so it could not figure out what the correct fstring was.
• were too long (it doesn't like lines longer than 88.

So doing a second pass looking at those manually. a day or so for a PR.

[petersilva]

See #1628. It should update the entire app to f-strings appropriately (except logger.debug)