I’ve given up trying to push against f-strings/format in log messages; I even wrote a bowler/fissix fixer to automatically transform our codebase from them/.format/%-format into the delayed form.
But nobody ever used it, and nobody changed the way they wrote them.
Admittedly it is convenient and usually reads better; I just gave up, even for my own code; if any become performance issues we can pick it up on profiling.
Setting aside the performance argument, strictly adhering to this rule makes a big difference in 3rd-party tools like Sentry. If you pre-format log messages, the parameters don't get captured, and (at least in my experience) it sometimes shows up as a separate event entirely.
Having written a monkeypatch for the stdlib logging library at Hipmunk (RIP) for our GDPR effort, I can say: I have a lot of thoughts about ``logging``, and few of them are good. But it's definitely better than print statements!
Bragging a little: I successfully convinced most of the people at my org to avoid pre-formatting the logging messages. On the other hand I'm "the weird one" because I'm the one who complain about it in the code reviews and I'm not sure everyone else follows my reasoning. But at least the code looks (subjectively) a bit better now!
If your code has a lot of debug and info statements, but you only set production to the warn level, then you’re wasting cycles interpolating strings that go nowhere.
I'd be curious to see that benchmark. I also don't have an initial guess about which would be faster:
* Format a string, pass it to a function, and the function decides whether to emit it, then how to render it.
* Pass in the template and parameters to a function, and the function decides whether to emit it, then how to render it.
F-strings are pretty darn fast. I don't know how much relative overhead there would be in calling the logging function, and in the logging function's decision tree about whether to emit a log message.
Well, the actual solution is that your log should not contain any formatted statements at all. Formatting should be done offline as a post-processing step when viewing/ingesting the log, not when producing the log.
While it might not be too visible in Python, formatting is a very significant cost. I work with systems that can output tens to hundreds of millions of log lines per second per core with the limiting factor being memory bandwidth. It would be pretty challenging in many systems to get even a tenth that rate. I can literally add 10,000 logs per second per core at a 0.1% system overhead. Pre-formatting your logs is convenient when just starting out, but you should really switch to a more efficient logging system pretty quickly.
That’s a use case I’ve never considered for Python’s logging module. Is that emitting a message for every iteration of an inner loop? It seems like your log analyzer would curse your name unto 3 generations for making it deal with that.
Auto-instrumenting every function call is the more common use case demanding those data rates. I mostly work in C, so the costs of doing that are in the 10-40% overhead range. In Python the overhead is in the single digit percent range. You deal with it by having good graphical log viewing tools.
Really, your problem is actually getting the logs off the system. When you generate logs at 15 GB/s per core the only device fast enough is RAM. If you want any logs larger than a circular RAM disk you need to deliberately slow down your logging rate so your ethernet can keep up.
Yes, but we’re specifically dealing with Python here. I’m extremely skeptical that anyone’s logging 15 GB/s in Python, or that it’s even possible using the standard library.
Much more likely is whether someone would call
LOG.info(“%s: %s”, request_ip, request_path)
or
LOG.info(f”{request_ip}: {request_path}”)
a few dozen times a second. I suspect it’s a pointless micro-optimization for 99.9% of use cases.
1,000,000 iterations of the flake8-happy logging took 0.090s. The f-string version took 0.264.
On one hand, the flake8 version is significantly faster if the log messages aren't emitted. On the other, the "slow" f-string version ran 4 million times a second while inside a timing harness. That's likely to be a trivial percent of any interesting program's CPU time unless it's inside a timing-critical inner loop, in which case don't do that.
For an extra data point, I bumped that up to `LOG.warning()` and re-ran the tests. A million flake8 runs took 4.617. A million f-string runs took 4.553s. If you're actually emitting the debugging record, f-strings are slightly faster. Huh, interesting. Today I learned!
I'll continue to use f-string logging in common cases. When it's slower, it's so very slightly slower that I don't care. But as others have mentioned, the `extra` argument when using flake8-style logging is brilliant for emitting structured data that's easier to parse later.
Something I have found to work well in Python is static log messages with details in the `extras` kwarg (especially if you’re formatting logs as json).
Surely string interpolation is cheap, especially given that we're talking about Python here?
I'd be more worried about cases where you're calling some function to produce a novel value that will then be included in the log string— and Python doesn't have lazy argument evaluation so you'll pay the cost of that function call regardless.
If it's CPython we're talking about, a function call can cause non-negligence performance impact in a hot loop. I wouldn't assume anything in Python is 'cheap'
I've been tooting this horn for months now and it still comes up in just about every PR review, despite trying to explain how log messages being static strings allow you to easily aggregate them so you can do further filtering based on separate fields containing runtime calculated values. It seems the allure of just shoving everything into a single message string is too strong.
I believe that "LOG011 avoid pre-formatting log messages" is a terrible rule, and I always push for the opposite in all the codebases we work on: always pre-format all messages.
The reason is simple: logging module made a weird decision to ignore all the formatting errors, which means that a lot of testing generally fails to find any logging problems.. Put "logger.info("Queue size: %d", 'hello')" int your source and it'll pass all the unit tests, all the system tests, and would only be detected in prod, at the worst possible time when the system is failing and someone really needs to know the queue size. It is much better to preformat the messages, so tests and IDEs catch it later.
And yes, there are some rare logging statement in the tight loop - and in this rare case you can add explicit "if logger.isEnabledFor(logger.DEBUG):" call.. This is annoying, but it should be pretty rare, you should normally avoid logging code in tight loops.
logging's formatter ignores errors. It will complain on console, but no exception will be raised, so the tests would pass. Unless you open test logs and manually examine output (and who does this for passing tests?), the test results will show green.
Not exactly, it does not ignore errors. First, an error doesn’t occur until a format op at/above level happens.
Change to log.error() for example and watch the fireworks.
Second, true it will continue on, but the error is well logged with a traceback. The thinking, I happen to agree with is that a logging error shouldn’t halt the program.
A logging error doesn’t cause an error in the program itself.
I could see an argument the other way in specific situations however. I’d probably subclass Logger instead if that is not configurable.
>Second, true it will continue on, but the error is well logged with a traceback. The thinking, I happen to agree with is that a logging error shouldn’t halt the program.
And the parameters are also logged, so you don't really lose anything should this somehow happen in production.
Better strategy I think is to disallow %d and others, which is never necessary in logs. Have always used either %s or %r without issue.
Linters will tell you if you have the wrong number of params and you’ll get a big exception at runtime as well. Better to avoid unnecessary work, imho.
%d is pretry useless, yes. But %.3d is great for time durations where millisecond resolutions are sufficient. Or %_d (group digits) for large numbers like filesizes.
Rereading I see your log level is the true culprit, which is postponing the errors. Not “prod” per se.
This problem you mention will continue to be hidden in prod until you drop log level.
Preformatting is one way to avoid but feels heavy handed.
I always develop at debug level so this never happens. In fact I changed the level default in our dev environment to debug for my own convenience, unrelated to this but prevents it as a side effect.
Your argument is that logging modules do not do proper type-checking on their format parameters, therefore you should pre-format all messages since pre-formatting forces the compiler/runtime to do the type-checks. Why not just solve the problem directly by just get a better logging module that does the checks? We already established the compiler/runtime can do the checks, it is just a question of getting the checks to run.
Also, frankly, a proper logging system implemented in C should be able to support tens of millions of logging statements per second per core. There is little reason to be stingy on logging even in optimized C let alone a language as slow as Python. A system where manually inserted logging statements constitute a material overhead almost certainly means your logging system should be improved.
> directly by just get a better logging module that does the checks
Because logging is a cross-cutting concern and the built-in logging module is the common denominator that packages in the Python ecosystem have to generate logs without knowing anything about the application they might be embedded into.
So while you're free to use whatever logging module in your own top-level code, your dependencies will use the logging module and you have to deal with that. Packages have to find a way to integrate with it https://www.structlog.org/en/stable/api.html#structlog.stdli...
> LOG005 use exception() within an exception handler
In Python, exception handling is part of the normal control flow. Therefore, when an exception happens, it is not always the case that you want to log a full stack trace.
log.exception is also usually bad when you are re-raising the exception. That often results in same stacktrace logged multiple times in a row which can be confusing or at least annoyingly verbose.
But it can be helpful to log an error message (without stacktrace) to give context that is available only in this frame before letting the exception propagate to whoever ultimately handles and logs it.
Why would you log an error for an expected path? That should just be an info or debug level log, not error. In any case, it's really easy to disable errors either by line, module or project if really necessary.
If you had said log.critical(), I might (might) have agreed with you. But a log.error() is not necessarily an error on the Python level, and should not necessarily spam a backtrace into the log.
It depends on the situation. There are cases when I "expect the exception" - for example anything that touches the network has a tiny chance of failing. I want to know how often this happen, because too many network errors probably means that something is down and needs to be investigated (and we have alerts for this, based on logs). But to be fair I usually just log .exception() in this case anyway (even if I know exactly what the exception will be).
Oh no, I would not necessarily log an exception, the same way I don’t log every time an ”else” clause is reached. But in the places I do want to log.error("something") in an exception handler, I don’t want some linter complaining that since there is an active exception, it thinks I ought to have used log.exception().
But nobody ever used it, and nobody changed the way they wrote them.
Admittedly it is convenient and usually reads better; I just gave up, even for my own code; if any become performance issues we can pick it up on profiling.