Your points about logging with care saving more cycles that logging efficiently is very right.

That said, here's how I've handled efficient logging in realtime threads since the old days of 100MHz processors: postpone the formatting to a non-realtime thread. Assume your log_printf() will have no more than 10 int-sized args. Grab and save the 10 "ints". When doing the format in the non-realtime thread, pass in the 10 ints. Obviously this won't work with every CPU arch, but it does work fine for all the most common ones. Now every time you do a log_printf(), 1 pointer and 10 ints are copied to a buffer, which is very quick.

The catch is that your format string must be not be changed (e.g. use a string literal). Also any strings you want to print must also be const.

> is that you will spend most of your time formatting strings if you do your file I/O asynchronously.

That's why you are supposed to do your formatting in the background thread :).

> doesn't matter how many millions of logs you can generate per second

Usually the issue is not generating millions of line of logs (in whitch case dispatching to a background thread just adds overhead), but being able to log with minimal overhead on the surrounding code.

> That's why you are supposed to do your formatting in the background thread :).

Which then has the drawback that every argument that gets transferred to the background thread must first be heap allocated or static - instead of only the final buffer being that. My gut feeling is that the additional allocation and memory management costs typically outweigh the cost of formatting in the current thread. Even if one pools all logging buffers less buffers are needed for transferring only formatted buffers.

Normally you would copy the arguments to be formatted. This is usually less bytes than the formatted output.

Or you'd copy them.

Unless you do something dumb (like copy a vector when you only need to print the size), copying is significantly faster than string formatting.

I think what OP is hinting at here is cache invalidation/eviction caused by the additional thread's processing and memory operations. If your requirements are down to nanosecond granularities then cache misses are probably being measured and noticeable. A third party logging thread doing memory copies and other log processing sounds like a fine way to unintentionally evict a bunch of cache entries. You might be able to mitigate this to some extent with CPU affinities for threads I suppose. Another option would be to move logging to the network and record packets in/out with an out of band monitoring solution.

Logging the raw structured log entry and off-loading any string formatting to another system is a very interesting idea. Just push the whole "friendly message" stuff off to other logging infrastructure where the latencies matter less.

Well yes, using another thread is a only good idea if you have an extra core available.

L1 cache is per-core anyway, and I doubt L2 is going to hurt much.

At a few places I've worked, logging and util stuff had it's own core to prevent l1/l2 cache pollution (either using threads or shared memory just as long as you got it out of the hot path).

Yes, but you need to have a location where to copy them to. They can’t be on the stack, since the logging task runs asynchronously. So each captured argument must be in some form heap allocated. Eg passing 2 strings as arguments and one integer might require 3 additional heap allocation - where the malloc/free overhead might outweigh the string formatting costs. You can try to optimize here with specialized allocators (eg Arenas) or trying to generate dedicated structures for each logging callsite where all arguments can be carried inside a single heap allocated struct (instead of 3 here). But that might lead to other disadvantages - eg code bloat.

That would be a terrible implementation strategy. You would simply copy each argument into the communication ring buffer. You can also use specialised strategies for some types, for example string contents can be transmitted inline instead of copying the strings themselves.

On my logger the thread queue was(is) node based, so it was just a matter of making a bigger contiguous allocation and placing things there contiguously, the log entry and the data copies. 1 allocation.

Good point

Shared memory to a background process is better, in that it can survive most classes of process crash.

Yes it is significantly more robust, the downside is that you have to copy everything, including static vars and format strings. An option is to fork early on process startup and possibly share some memory.

We simply catch all signals and do a best effort attempt to flush the queue before aborting.

I've dealt with this problem too, mostly in trying to log/debug real-time media processing where a log trace equivalent would be long chunks of floating point data at multiple trace points in the data flow.

I came to the same conclusion. Raw bandwidth to your logging endpoint is meaningless when you start dealing with big chunks of information, which is common sense I guess. You need a fast way to digest it into whatever format works for the person reading the log later, and it's tough to make it abstract since how data is interpretted can be quite varied even in the same application.

> you will spend most of your time formatting strings if you do your file I/O asynchronously

Which is why good logging systems try to defer as much formatting logic as possible until the last possible moment (ideally render time).

I wish more logging frameworks would log in some efficient intermediary serialization format like Cap'nProto or Protobuf.

This is, of course, true. Many fail with the mindset that if only they can build big enough haystacks, the needles will coalesce like shiny seaglass upon the shore, because surely they will hire the algorithmic wizards, and oh yes.. AI(!!) and ML(!!).

Still, this really could have useful applications in scientific applications where the goal is to capture extremely fast events in detail... super-colliders, fast-fusion events, etc...

That's why I open comments first.. hypetaker +1