6 ms·

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/.for

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.

touristtam 3y ago
Isn't the argument about lazy loading?
- ochoseis 3y ago
  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.
  - kolanos 3y ago
    This just makes me wish fstrings had a lazy interpolation mode.
  - kstrauser 3y ago
    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.
    - Veserv 3y ago
      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.
      - kstrauser 3y ago
        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.
        ochoseis 3y ago
        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).
        Veserv 3y ago
        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.
        kstrauser 3y ago
        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.
  - mikepurvis 3y ago
    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.
    - RandomBK 3y ago
      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'
      - squeaky-clean 3y ago
        Relative 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 ago
  A more obscure one is about handling the exception when __str__ or __repr__ raises.
nbadg 3y ago
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!
- nicbou 3y ago
  This is why we started doing it too. It allows grouping of related messages, even if the parameters and formatted string change.
paulddraper 3y ago
Scala has a very useful feature: pass-by-name. It implicitly constructs a lambda for the argument.
msm_ 3y ago
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!
Hamuko 3y ago
If 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 ago
They learned after a few blocking reviews and an example of why it’s better to aggregate in splunk
- nevon 3y ago
  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.

touristtam 3y ago

Isn't the argument about lazy loading?

ochoseis 3y ago
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.
- kolanos 3y ago
  This just makes me wish fstrings had a lazy interpolation mode.
- kstrauser 3y ago
  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.
  - Veserv 3y ago
    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.
    - kstrauser 3y ago
      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.
      - ochoseis 3y ago
        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).
      - Veserv 3y ago
        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.
        kstrauser 3y ago
        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.
- mikepurvis 3y ago
  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.
  - RandomBK 3y ago
    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'
    - squeaky-clean 3y ago
      Relative 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 ago
A more obscure one is about handling the exception when __str__ or __repr__ raises.

nbadg 3y ago

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!

nicbou 3y ago
This is why we started doing it too. It allows grouping of related messages, even if the parameters and formatted string change.

paulddraper 3y ago

Scala has a very useful feature: pass-by-name. It implicitly constructs a lambda for the argument.

msm_ 3y ago

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!

Hamuko 3y ago

If 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 ago

They learned after a few blocking reviews and an example of why it’s better to aggregate in splunk

nevon 3y ago
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.