2 ms·

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%

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

by Veserv 3y ago

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.