Flake8-Logging
adamj.eu
adamj.eu
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.
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!
It implicitly constructs a lambda for the argument.
* 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.
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.
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.
Much more likely is whether someone would call
LOG.info(“%s: %s”, request_ip, request_path)
LOG.info(f”{request_ip}: {request_path}”)
import logging
import timeit
LOG = logging.getLogger()
ip = "1.2.3.4"
request = "/index.html"
duration = 1.5
print(timeit.timeit("LOG.info('%s: %s (%s)', ip, request, duration)", globals=globals()))
print(timeit.timeit("LOG.info(f'{ip}: {request} ({duration})')", globals=globals()))
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.
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.
Basically, if you're worried about string formatting overhead, it's probably time to ditch Python.
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.
In case you’re already doing it, it is the rare occasion that I can unsarcastically say you’re doing it wrong.
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.
And the parameters are also logged, so you don't really lose anything should this somehow happen in production.
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.
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.
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.
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...
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.
try:
thing = things[0]
except IndexError:
log.error("Not enough things!")
return
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.
If it’s expected, I tend not to log it.
This rule is only for error calls, though. In that case, yeah, you wouldn't log an error for an expected path.