5 ms·
Flake8-Logging
- EdwardDiego 3y agoNice! I'll try this in our project tomorrow, I suspect it'll be bad.
- misnome 3y agoI’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.
- touristtam 3y agoIsn't the argument about lazy loading?
- ochoseis 3y agoIf 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.
- kolanos 3y agoThis just makes me wish fstrings had a lazy interpolation mode.
- kstrauser 3y agoI'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.
- Veserv 3y agoWell, 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.
- kstrauser 3y agoThat’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.
- ochoseis 3y agoSomething 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).
- Veserv 3y agoAuto-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.
- kstrauser 3y ago
- mikepurvis 3y agoSurely 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.
- RandomBK 3y agoIf 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'
- squeaky-clean 3y agoRelative to python it's cheap. A set of Ferrari tires for $1000 is simultaneously expensive but also very cheap compared to the normal cost. Basically, if you're worried about string formatting overhead, it's probably time to ditch Python.
- sirlantis 3y agoA more obscure one is about handling the exception when __str__ or __repr__ raises.
- nbadg 3y agoSetting 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!
- nicbou 3y agoThis is why we started doing it too. It allows grouping of related messages, even if the parameters and formatted string change.
- paulddraper 3y agoScala has a very useful feature: pass-by-name. It implicitly constructs a lambda for the argument.
- msm_ 3y agoBragging 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!
- Hamuko 3y agoIf you need to ensure that other developers do something, you need to make it a CI rule and make sure it fails if it's not done.
- baq 3y agoThey learned after a few blocking reviews and an example of why it’s better to aggregate in splunk
- nevon 3y agoI'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.
- sirlantis 3y agoRelated ruff rule: https://beta.ruff.rs/docs/rules/logging-f-string/ https://beta.ruff.rs/docs/rules/logging-f-string/
- nbadg 3y agoAlso, ruff has an issue to implement all of the rules. OP, excellent idea, and also, hats off to the ruff team, really: https://github.com/astral-sh/ruff/issues/7248 https://github.com/astral-sh/ruff/issues/7248
- charliermarsh 3y agoThank you for the kind words :)
- acdha 3y agoYou’ve made my Python projects more enjoyable this year more than any other change I can think of
- drcongo 3y agoLoved the little message to Charlie Marsh at the end of the OP.
- theamk 3y agoI 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.
- Veserv 3y agoYour 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.
- Spivak 3y ago> 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.stdlib.recreate_defaults https://www.structlog.org/en/stable/api.html#structlog.stdli...
- teddyh 3y ago> 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. try: thing = things[0] except IndexError: log.error("Not enough things!") return I think that even recommending a log.exception() here would actually be a bad thing.
- deleted 3y ago[deleted]
- kamikaz1k 3y agoIf it’s expected control flow, would you log it? If it’s expected, I tend not to log it.
- msm_ 3y agoIt 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).
- teddyh 3y agoOh 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().
- globular-toast 3y agoDepends what you're logging. An info level log is quite explicitly for an expected path, e.g. "config not found, using defaults". This rule is only for error calls, though. In that case, yeah, you wouldn't log an error for an expected path.