W1202 - logging-fstring-interpolation is not useful

[pzelnip]

Is your feature request related to a problem? Please describe

In my experiments W1202 is misleading as f-strings performance is virtually equivalent to %-operator formatting in practice.

Describe the solution you'd like

W1202 be deprecated, as it can lead people to not use f-strings, which (if available) are the preferred mechanism for string interpolation.

Additional context

This is related to my inquiry around this warning: #2354

To verify my hypothesis that f-strings are virtually as performant as %-operator formatting I wrote the following snippet to explore timing related to log statements with the 3 approaches (f-strings, .format(), and %-operator). This was on a Django app I'm working on.

import timeit

def timeitex1(num_times):
    fstring = timeit.timeit(
        'logging.info(f"""this is a {thing}, and thing: {thing + "blah"}""")',
        setup="import logging ; thing='1234'",
        number=num_times,
    )

    formattim = timeit.timeit(
        'logging.info("this is a {}, and thing: {}".format(thing, thing + "blah"))',
        setup="import logging ; thing='1234'",
        number=num_times,
    )

    percentop = timeit.timeit(
        'logging.info("this is a %s, and thing: %s", thing, thing + "blah")',
        setup="import logging ; thing='1234'",
        number=num_times,
    )

    return (fstring, formattim, percentop)

With logging output disabled (ie in my Django settings I had: LOGGING["loggers"] = {}), %-formatting and f-strings are virtually identical.

num_times = 10,000:
(0.016536445124074817, 0.02152163698337972, 0.018616185057908297)

num_times = 100,000:
(0.16004435811191797, 0.20005284599028528, 0.1561291899997741)

num_times = 1,000,000:
(1.641325417906046, 2.0023047979921103, 1.6249939629342407)

Returned times are tuples of "time for f-strings", "time for the format() call", and "time for %-formatting".

That's a difference of ~1% (1.641325417906046 vs 1.6249939629342407 seconds) between f-strings & the %-operator on the largest run (.format calls being clearly slower).

With logging enabled, it's a total wash (technically f-strings was the winner in the larger runs but by such a small margin it's inconsequential). This is with log output going to standard out (so I only went up to 100,000 entries as I didn't want to dump 3 million log statements to my console):

num_times = 10,000:
(1.6245153648778796, 2.0137458329554647, 1.6029843359719962)

num_times = 100,000:
(4.39409149507992, 4.51585376705043, 4.532764581032097)

So basically unless you are emitting a ton of logging statements for a level that are never actually logged (say because the LOG_LEVEL is set high), then it doesn't matter. And if you're in that scenario, then really there's no noticeable difference between %-operator formatting or f-strings (just don't do .format() calls).

OTOH, if you are emitting the logging message, then it's likely that the f-string approach will be faster, so following W1202 will actually make your code (extremely slightly) slower.

[Steffan-Ennis]

Have a read of #1788, fstrings are gone for good

[FrankDMartinez]

How about an option to exempt f-strings? By default, f-strings would be flagged; with the option, no.

[mcallaghan-bsm]

Do we have consensus on this? We too feel this should be deprecated.

As of Python 3.6 the recommended way to do this is with a formatted string literal. https://docs.python.org/3/reference/lexical_analysis.html#f-strings

Note that there are TWO warnings that could come ...

# python3 -m pylint blahblah.py 
************* Module blahblah
blahblah.py:8:13: W1202: Use % formatting in logging functions and pass the % parameters as arguments (logging-format-interpolation)
blahblah.py:11:0: W1203: Use % formatting in logging functions and pass the % parameters as arguments (logging-fstring-interpolation)

This is from:

MY_VAR_BAR = 'ywah'
_LOG.warning('foo %s', MY_VAR_BAR)
_LOG.warning('foo {}'.format(MY_VAR_BAR))
_LOG.warning('foo {MY_VAR_BAR}')
_LOG.warning("foo {MY_VAR_BAR}")
_LOG.warning(f"foo {MY_VAR_BAR}")

go

# python3 blahblah.py
foo ywah
foo ywah
foo {MY_VAR_BAR}
foo {MY_VAR_BAR}
foo ywah

Of note, in our .pylintrc file, we did already bump it to new format for logging-format-style...

[LOGGING]

# Format style used to check logging format string. `old` means using %
# formatting, while `new` is for `{}` formatting.
logging-format-style=new

[earonesty]

This is a per-project issue. We're writing a filesystem. There are certain points in the code where we have TRACE level logging. These are hit millions of times and interpolation can kill performance. Even DEBUG level f-strings can slaughter the functioning of low level code.

On the other hand, the readability of f-strings should generally be preferred when the number of interpolations isn't significant. In this case, providing developer with linter tools and options that help them make smart decisions is the right choice... not arbitrarily deprecating or enabling an option that has, at least for me personally, rescued seriously broken code.

Many pylint settings fall into this nuanced trade-off range, where considerations of readability, code complexity, etc. need to be balanced against each other and there are not easy choices. These generally cause controversy, and repeated issue tickets (this one is the 3rd!):

#2354
#1788

This could be an indicator that pylint needs more nuanced options to allow configuration of the linter depending on the nature of the project.

See: #3000 for an example.

[mcallaghan-bsm]

In addition to @earonesty 's comment above, another consideration MAY be that if we add clarity and documentation to these such nuanced warnings, the projects and users can make better educated decisions on their own.

(In this example, the information available at the moment for the fstring-interpolation warning leads to confusion and at worse developers NOT using this for non-performant required code which hurts readability unnecessarily)

[tristanbrown]

@earonesty, I think the point that's missed here is that the purpose of pylint is not to make every project's algorithmic decisions for them, but to make code generally consistent for readability purposes. The cases where the performance of interpolation matters seem particularly niche, whereas the cases where f-strings enhance readability are broad and varied.

In that sense, -in general- f-strings should be favored by default by style-checkers. The few projects where f-strings cause performance problems can set non-default configurations.

[chdsbd]

Here’s a copy of a comment I made on #1788. #1788 (comment)

It seems like everyone here is talking about performance. There are other benefits to letting logging do the interpolation.

1. if interpolation fails, it will be logged instead of raising an exception
2. things like Sentry can aggregate log messages. If you interpolate before logging, Sentry would see it as one event 0

[earonesty]

I've come around to the idea that f-strings are almost always a bad idea, certainly in logging. The run-time implications and side-effects of the f-string eval() simply don't belong in logging statements.