logger-thread: A low latency threaded logger

Inobtrusive logging

Logging (or tracing) is an essential part of application development. It is needed for developers as the first-line debugging tool, for integrators to debug dependencies and configuration, for operators to understand what the application is doing, and for end users to report bugs.

However, it comes at a cost. At some point, there is a system call to send the data out. System calls can be intrusive in the flow of the program. In particular if it’s a real-time program, the system call will inject unbounded latency at the point that a log is made. In addition, in a multi-threaded program, there will be implicit serialization because all the logging output goes into a single stream. 

The logger-thread library implements inobtrusive logging by moving the possibly-blocking system calls to a separate thread. It is fully open source software under an MIT license. It can be found at https://github.com/ledav-net/logger-thread

Lock-free threaded logging

In order to hide the system call latency when performing a logging action, logger-thread uses a separate thread to do the actual logging. When a log call is made in the application code, the log message string is simply added into a dedicated circular buffer and the logger thread then retrieves the log messages and serializes them to the output. The logger thread can run at a lower (non-real-time) priority than the other threads.

Spooling the log messages to the circular buffer is non-blocking and non-serializing. It is implemented using a single-reader-single-writer approach. One message buffer is allocated per thread that needs to perform logging and a pointer to it is put in a thread-local variable. Writing to the circular buffer is done by updating the write pointer and comparing it with the read pointer using atomic operations. No blocking operations are involved, unless the buffer is full.

The logger thread reads from each of the circular buffers and prints out the log messages in chronological order. A timestamp associated with each message at the moment it is logged, not at the moment it is printed; thus, the logger thread makes sure the messages are output in order of increasing timestamp. The timestamp is created with clock_gettime(). On Linux, on most architectures, this is not a true system call but is rather implemented with vDSO. Therefore, it does not cause blocking or too much latency.

If all the ring buffers are empty, the logger thread goes to sleep. To wake it up again at lowest cost, the futex mechanism is used to synchronize between the threads. Although this is an actual system call, the FUTEX_WAKE operation is not blocking and very fast. It is also only called if there is actually a need to wake up the logger thread.

If a writing thread’s buffer is full, the library has the option to block after all, or to just give up and discard the log message. In the latter case, a counter of dropped messages is incremented and as soon as the logger thread ends up reading from the buffer again, that counter can be printed also for debugging.

Configuration options and features

The library is very flexible and covers many different scenarios. Many configuration options can be used during runtime and compile time. 

There is both a compile-time and a runtime option for the minimum error level message. Set at runtime, it will filter the messages to output. At compile time, the code will be stripped out from the final binary. This is useful to strip debug messages that can contain sensitive information or to implement a verbose argument to turn on debug messages when needed.

There is also a compile-time option to not block when the circular buffer is full. In that case the message is lost and an error is returned to the caller. Another option can be turned on to print the number of messages lost as soon as there is some space freed.

The message buffer is normally allocated when the writer thread is started. If it is not allocated then, it will be allocated the first time a message is logged. However, that allocation would again be obtrusive in the normal flow of operation, that’s why it’s done at thread creation by default. Still, there’s an option to delay until the first message.

The log levels are compatible with syslog messages. Currently, the logger-thread library only has a file as output, but it would be very easy to implement an option to send the output to syslog instead.

By default, ansi colors are used but other “color schemes” can be defined, used and toggled at runtime if needed.

It is also easy to switch off logging completely at compile time. Alternatively, you can switch to direct printf() without buffering or a logging thread. This is useful if your functions can be part of a library and dont need a logger thread in that context. The same code can be compiled for both use cases.

For the complete list of supported features & options, please read the README.md file and C headers from the main github repository.