6 ms·
Nanolog supports logging with 7 ns median latency
- zdw 2y agoDoesn't a logging system need a storage system that can keep up with it, if the goal is to persist logs for later analysis? What storage could keep up with this?
- rfoo 2y agoThis is for very bursty logs. You don't log every 7 ns. On average you are not generating a huge amount of logs. But you need each logging call to be very fast, cause logging calls are usually synchronous.
- dangsux 2y ago[dead]
- mannyv 2y agoIf the logging call is in the critical path then logging data is probably critical as well. After all, the fastest call is the one you don't do. If you're writing telemetry then that's different. But if you're using logging to write your telemetry then there are better ways to do it.
- wdfx 2y agoI think the idea here is to separate the log call site in application code from the log processing/persistence? So, the nanosecond values quoted are the impact exposed to your application code, but some other process takes over the bulk of the work of the logging. So as long as the offloaded process can keep up with the average log rate, it'll be fine - but also as a bonus the application does not see increased latency due to logging.
- 01HNNWZ0MV43FF 2y agoSounds a bit like how Tracy works
- deleted 2y ago[deleted]
- cma 2y agoBattery backed SRAM
- username81 2y agoAre there libraries like this, but in rust? As far as I understand, it relies on C's preprocessor, so it is impossible to create bindings for another language.
- cmptrnerd6 2y agoI have not used this and it says it targets embedded systems but maybe it is close enough to what you might be looking for: https://github.com/knurling-rs/defmt https://github.com/knurling-rs/defmt
- steveklabnik 2y agoI have used this, but not the library in the link. From the link’s README, they’re at least analogous. While maybe not the exact same thing, they’re at least the same idea.
- deleted 2y ago[deleted]
- eventhelix 2y agoStallone is another option for Rust: https://github.com/GaloisInc/balboa/blob/main/stallone/log/src/lib.rs https://github.com/GaloisInc/balboa/blob/main/stallone/log/s...
- andrepd 2y agoSounds like something that would be doable in rust. I'm not sure how you would go about building the compile-time table of log locations and format strings, sounds like the hardest part.
- wtetzner 2y ago> I'm not sure how you would go about building the compile-time table of log locations and format strings, sounds like the hardest part. Sounds like a job for a macro.
- cmptrnerd6 2y agoI've used https://github.com/rokath/trice https://github.com/rokath/trice which is similar but targeting microcontrollers. It isn't immediately clear to me if nanolog could run on a microcontroller with its output directed over RTT/uart/etc or not.
- fra 2y agoThis is a common technique in embedded software. A few other examples: 1. Thrice (already mentioned in the comments) https://github.com/rokath/trice https://github.com/rokath/trice 2. Pigweed's Tokenizer (from Google) https://pigweed.dev/pw_tokenizer/ https://pigweed.dev/pw_tokenizer/ 3. Memfault's Compact Logs https://docs.memfault.com/docs/mcu/compact-logs https://docs.memfault.com/docs/mcu/compact-logs 4. Defmt by Ferrous Systems https://defmt.ferrous-systems.com/ https://defmt.ferrous-systems.com/
- frizlab 2y ago5. macOS logging system https://developer.apple.com/documentation/os/logging/viewing_log_messages https://developer.apple.com/documentation/os/logging/viewing...
- deleted 2y ago[deleted]
- enigmo 2y ago6. WPP in Windows 2000 ETW https://learn.microsoft.com/en-us/windows-hardware/test/weg/instrumenting-your-code-with-etw https://learn.microsoft.com/en-us/windows-hardware/test/weg/...
- lokar 2y agoThe google logging library also defers formatting
- odygrd 2y ago7. https://github.com/odygrd/quill https://github.com/odygrd/quill More modern than nanolog and also type safe supporting any type
- perching_aix 2y agothat sounds deliciously performant, love projects like these
- yas_hmaheshwari 2y agoI was also thinking the same~ How come such a good idea is already not part of standard logging libraries -- to allow you to configure to another process or message queue! Loved the idea
- Validark 2y agoAmazing work! I was wondering just a few months ago whether someone ever made a logger that deferred all the expensive work of string formatting to consumption time. ~~I'm a bit surprised that it didn't come along sooner though. How come nobody at Google or VMware who said they noticed this was a problem solved it? Or any other major tech company? I guess maybe this is partially an issue with our programming languages and build tools though? I'm a Zig enthusiast though so in my head it's trivial, but I guess it won't be until C++26 that they get potentially comparable comptime facilities for C++.~~ I'm surprised Go doesn't work like this by default though. For a language like Go, I'd have made a builtin log keyword that does this. EDIT: Looks like other implementations of similar ideas do exist. Still awesome though!
- yuliyp 2y agoYou have to be careful in deferring such work. It may end up more expensive if it means you have multiple threads accessing that data, and/or needing to extend the lifetime of an object so the logger can access it.
- jnordwick 2y agoas long as you are just using static strings and native types it amounts to a pointer/index bump and a load/store per item. Lets imagine you have the format string, priority number, system id, and 7 pieces of data in the payload. That would be 10 items, so like 40 cycles? I can see the 18ns the paper gets. I had no doubt the 7ns number is heavily cooked.
- yuliyp 2y agoIf those pieces of data are strings or more complicated that might be manipulated/freed later you might need to do something more like copying.
- lokar 2y agoThe google logging library has deferred the formatting for years
- geertj 2y agoThe consumer side of this would be polling a memory location for new logs, correct? It would not be possible to wake up the consumer in 7ns as that would take a FUTEX_WAKE system call with is O(microseconds). I've been wondering about a FUTEX_WAKE that does not require a system call. Possibly, the kernel could poll a global memory area. Or maybe there is some low-level debugging API available where the kernel could be notified of a memory write by a process?
- gpderetta 2y agoThere isn't a significant advantage in having the kernel doing the polling, it would still be busy polling. If you just don't want to burn power but you can still dedicate a core, there is https://www.felixcloutier.com/x86/mwait https://www.felixcloutier.com/x86/mwait.
- geertj 2y ago> There isn't a significant advantage in having the kernel doing the polling, it would still be busy polling. I was thinking in terms of a generic syscall-less wake functionality where the kernel could do this for all processes in the system. So you'd lose one core per system instead if one core per consumer. >If you just don't want to burn power but you can still dedicate a core, there is https://www.felixcloutier.com/x86/mwait https://www.felixcloutier.com/x86/mwait. Interesting. Could be used to make the kernel loop above burn less power. A user-space implementation could presumably also be built. There could be a shared memory segment shared between producers and a monitor. A producer sets a flag in case it needs attention, and the monitor busy polls the segment. The monitor could then use e.g. a signal to wake up consumers. The latency between the producer signaling and the consumer taking action would be a higher than with futexes. But there would be no waits/context switches in the producer at all. Might be a solution for some low latency use cases.
- toxik 2y agoO(microseconds) = O(years), this is not what big O notation means.
- jnordwick 2y agoIt uses a background thread to do most of the work, and it appears the 7ns latency numbers are a little cooked: 1. The paper's 7ns like number is 8ns for microbenchmarks but 18ns in applications. The 7ns number I'm guessing is microbenchmarks, and the true application level number is prob more in the 17ns range. 2. It isn't precisely clear what that is measuring. The says that is the invocation time of the logging thread. Considering the thread making the call to log just passes most of the work to a background threads through a multi-producer single consumer queue of some sort, this is likely the time to dump it in the queue. So you really aren't logging in 7ns. The way I'm reading this is you're dumping on a queue in 17ns and letting a background thread do the actual work. The workload is cut down by preprocessing the creating a dictionary of static elements do reduce the I/O cost of the thread doing the actual writing (I assume this just means take the format strings and index them, which you could build at runtime, so i'm not sure the pre-processing step is really needed). My logger than dumps binary blobs onto a ring buffer for another process to log might be able to beat this invocation latency. This isn't really groundbreaking. I know a few place that log the binary blobs and format them later. None of them do the dictionary part, but when that is going to a background thread, I'm not sure how much that matters.
- szundi 2y agoOnly thing that makes sense is that the thread sending the logs is blocket for 7ns - otherwise too much context dependent extra comes in to make a claim like this
- gpderetta 2y agoYes, the overhead in the logging thread is what this is trying to minimize. The background thread is considered "free". This sort of async logging is a common setup for some class of applications. And yes, it boils down to writing data to a message queue. Most of the overhead is probably the call to the hardware timestamp counter.
- jnordwick 2y agoIn my logging code I wrote that is basically a SPSC ring buffer, I use some RDTSC assembly and at startup I calculate the frequency and epoch offset. It has a throughput of around 30 cycles. That's already ~10 ns, so I'm not sure how they are getting their numbers. If they are timestamping the data when the background thread gets to it that would be pushing even more work to it. It guessing they do or else they could potentially be logging out of order data with multiple threads.
- packetlost 2y agoI have ideas for a logging/wide metric system that uses this technique and some others stolen from DNS and IP. It's largely inspired by a combination of a system I've built at my day job that implements distributed command & control for servo-ing, monitoring, etc. It's been really successful, but the hardest part is mapping a unique numeric identifier to a human readable string in a way that is dynamic and efficient enough. It really seems like the exact same problem as DNS, which leads me to believe there's likely no way without a persistent centralized registry/database.
- kolbe 2y agoI could swear I did a deep dive into Spdlog vs Nanolog six months ago, and the performance differences weren't nearly this stark
- synergy20 2y agowhat do you mean? considering spdlog is the de facto logger for c++
- kolbe 2y agoNano is claiming insanely better performance over spdlog, which confuses me
- odygrd 2y agospdlog is designed as a general purpose logging library and it can’t beat low latency loggers. It doesn’t scale for multiple threads because it’s async mode is using a mutex and a cv to notify the background thread. You can find some logging libraries benchmarks here https://github.com/odygrd/quill?tab=readme-ov-file#-performance https://github.com/odygrd/quill?tab=readme-ov-file#-performa...
- linhns 2y agoI believe the performance reported in their paper is circumstantial. It’s not that much faster when I tried it, and not worth the horrible macro syntax.
- swah 2y agoSo you're actually spawning threads in this simple C++ example? I thought this was refrained in C++ land... #include "NanoLogCpp17.h" using namespace NanoLog::LogLevels; int main() { NANO_LOG(NOTICE, "Hello World! This is an integer %d and a double %lf\r\n", 1, 2.0); return 0; }
- bazzargh 2y agoThe paper says a lot of the secret sauce is dumping a dictionary of the static content and then logging in a binary format. That format looks a lot like gzip, if you squint. Could something like this use the _actual_ gzip format, but writing with a static dictionary, to make life easier for tools? (gzip has a trailer, but I'm not sure how much attention is paid to that, since it's often used for streams)
- newobj 2y agoThe real headline here is that log4j2 is faster than Boost.Log
- eska 2y agoThere’s a reason why many avoid boost.
- loeg 2y ago7ns latency is in the ballpark of small writes to L1 cache. I.e. some sort of in-mem only append to somewhere predicted by the prefetcher of like, a single cache line or less. So yeah, some sort of ringbuffer log could definitely support this kind of figure. The question is how much throughput does your persistence channel have, how much memory can you devote to logging while your persistence runs async, are you ok with a somewhat volatile log, etc.
- jnordwick 2y agoyou don't really wait on L1 cache writes though. The store buffer absorbs it, and if the data is needed it can be forwarded from there before the write to cache even happens. Most x64 L1d caches have a 4-6 cycle latency depending on CPU, that 1 to 2 ns depending on frequency.
- deleted 2y ago[deleted]