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.
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.
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.
I have also seen people make the logger into dso so they can dump strings from main app binary and record addresses to avoid the hassel of preregistering. but with preregistering I was able to get the perf all the way down to ~40ns per message w/o the separate log dumper thread. at that point you actually start running into disk IO limitations.
one additional thing I did was to create the ring buffer in a shared memory segment and log to that from all services in the system. so this way you dont even have to think about crashing services. anyway the point is this hardly seems groundbreaking. what I'd like to see is this evolve into a fast syslog type service when one just freely logs trace messages throughout w/o worry about the cost and we can use them for postmortem analysis or filter at dump.
I thought log4j2 used a disruptor in between app thread and logging thread but maybe I’m wrong.
As we now know the syscalls to force flush to disk often didn’t, so if you were trying to figure out what happened right before a kernel panic, good fucking luck. But if it was a purely userspace problem, you might be okay.
These days we care more about throughput. I’d personally rather see us commit to stats for use cases that require that sort of logging traffic, but I think that’s one of those conversations that’s nearing the top of the heap. Maybe we’ll have that argument as soon as we stop flooding the literature with talk of AI.
So 7ns tells me something about throughput but I think i’d rather just know the messages per second per CPU. And perhaps more importantly, with a CPU that’s 80% saturated doing non-logging tasks. Because I need to make forward progress between the log messages.
1. Thrice (already mentioned in the comments) https://github.com/rokath/trice
2. Pigweed's Tokenizer (from Google) https://pigweed.dev/pw_tokenizer/
3. Memfault's Compact Logs https://docs.memfault.com/docs/mcu/compact-logs
4. Defmt by Ferrous Systems https://defmt.ferrous-systems.com/
More modern than nanolog and also type safe supporting any type
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?
Most x64 L1d caches have a 4-6 cycle latency depending on CPU, that 1 to 2 ns depending on frequency.
But you need each logging call to be very fast, cause logging calls are usually synchronous.
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.
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.
#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;
}~~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!
I had no doubt the 7ns number is heavily cooked.
Sounds like a job for a macro.
Loved the idea
Since you are preprocessing the log messages and you know the minimum bounds. If the thread sleeps for 1 ms. Be generous and say you can at most push to the queue in 5ns, and if you know the largest messages you push will be 200 bytes, you can statically determine a 40M ring buffer will ensure enough space to sleep even at max rate with the largest messages.
And that's just a simplstic scheme. If you have a pool logging structs so your queue is just a pointer to one of those, you can get away with much less even.
And I can think of faster ways too. It isn't that difficult to get around using a semaphore
If you just don't want to burn power but you can still dedicate a core, there is https://www.felixcloutier.com/x86/mwait.
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.
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.
At steady state, the consume is either blocked on I/O or is scanning the producer buffers. When all producer buffers are empty, it can just sleep for a short time.
And in fact ... the wait-free wakeup part of this is already there. Now that io_uring has futex support, a producer can enable kernel-side busy polling on the uring, and then submit a FUTEX_WAKE to the ring without doing any sys calls. This Github issue [1] has a nice description.
You can find some logging libraries benchmarks here https://github.com/odygrd/quill?tab=readme-ov-file#-performa...
It could enable a full user space uring without the need of kernel side polling.
Timestamps will be somewhat inaccurate but it may help performance.
The fastest for nanosecond precision (bonus is this is even sub nanosecond) is just to store the return value of RDTSC and let the background thread figure it all out. You don't even need to precalcuate the freq or epoch offset. Just write a couple logging messages of the rdtsc value and CLOCK_REALTIME and let the post processing figure it out.
To cut down on I/O each log message's timestamp can just be an offset from the last even.
If you are willing to push a lot of work to the background thread and even more to the post processsing step, you really don't need to do very much.
Not sure it matters a lot of to have multiple messages with the same timestamp, since they were added in order you still know which one is older, the problem might arise when you send those logs to a remote place and the order of insert is discarded and the timestamp is used instead.
I assume that when you use a single thread with a queue / ring buffer the order of insertion is kept.
If you have an event loop, it might be acceptable to sample the counter once per iteration, but less than that it becomes too lossy.
You had the OS down-clocking cores to avoid CPUs cooking themselves, causing time to increase an inconsistent rates. Your app queried the clock rate, but unless it kept querying it, the number of cycles was meaninglesss.
ie:
(CPU rate changed to 1GHz)
Query Rate, 1GHz.
(CPU rate changed to 700MHz)
Read start time
Read end time
convert delta into time, using 1GHz rate... not accurate.
(CPU rate set to 1GHz)
Read start time
Read end time
(CPU rate set to 700MHz)
Query rate, 700Mhz.
convert delta into time, using 700MHz rate... not accurate.
It was a mess. Windows introduced a call to get time in a safe way, as they knew when they changed CPU frequencies. Intel fixed the hardware to use a constant clock after a just a few models, but the damage is done... It's invariant...usually, but not for certain.
You can verify it's invariant through one of the cpuid leaves. There's a feature bit.