5 ms·

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

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.
        kstrauser 3y ago
        I tried it for science: 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())) 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.
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.

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.
      - kstrauser 3y ago
        I tried it for science: 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())) 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.

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.