5 ms·
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
by 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 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 agoYes, 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 agoI 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.