TL;DR

NanoLog is great where there is a critical need for high-performance logging. It shifts the work from runtime to compile-time and post-execution phases and a throughput of up to 80 million log messages per second with the log invocation overhead of just 8 nanoseconds.

NanoLog serializes log messages into a compact binary format at the time of logging and deferring the emission of logs to a separate thread, all while maintaining a lock-free operation and reducing the I/O bandwidth requirements. Three things that I found most interesting are:

1. compile-time optimization and specialized code generation for each log statement
2. lock-free, cache-optimized circular buffers
3. custom lightweight encoding and compression scheme

Three interesting things

Continuing the discussion from the above TL;DR, here are three things that I found interesting in this paper and some quick details about each.

Compile-time optimization and code generation

One of the most fascinating aspects of NanoLog is its use of a preprocessor to perform compile-time optimizations. This approach shifts a significant portion of the work traditionally done at runtime to the compilation phase. The preprocessor analyzes each NANO_LOG() statement and generates two specialized functions:

• record() - captures only the dynamic data for each log message,
• compact() - optimized for efficient compression of that specific log entry.

The preprocessor extracts type information from the format string (e.g., “%d %f” indicating an integer followed by a float) and generates type-specific code for handling each argument. This eliminates the need for runtime parsing and type inference, which are typically expensive operations in logging systems. Thus we get extremely fast logging with the ease of use of a printf-like API.

Lock-free, cache-optimized staging buffers

NanoLog’s use of lock-free logging, with circular buffers, to avoid locks, contention, and cache coherency issues in multi-threaded environments. This buffer is per logging thread, implemented as a single-producer, single-consumer circular queue. Each log message is serialized and atomically placed into the next available slot in the circular buffer.

The circular buffer, being a fixed-size FIFO queue, provides predictable memory usage and minimizes cache misses, which is critical for maintaining high throughput. NanoLog also does micro-optimizations by arranging data to avoid false sharing by placing the private variables for the logging and background threads on separate cache lines.

Lightweight encoding

Instead of formatting log messages into human-readable strings at runtime, which is computationally expensive, NanoLog serializes the parameters into a compact binary format. It performs binary serialization directly at the point of logging and the log message is not converted into a string; instead, the data is serialized into the binary format which is much faster to generate and easier to store.

Instead of using standard compression algorithms like LZ77, which proved too computationally expensive for real-time logging, NanoLog uses a lightweight compression scheme specifically for integer types. This decision is based on the observation that most logged integers are relatively small and don’t use all the bits of their type.

The compression encodes integers using the minimum number of bytes necessary, with a 4-bit nibble of metadata to indicate the number of bytes used and whether the number is negative. This provides a good balance between compression ratio and computational cost, which is crucial for a high-performance logging system. The scheme can represent small integers (positive or negative) in as little as 1.5 bytes, including the metadata.

Notes and a quick explanation

Logging is fundamental and traditional logging systems have a significant overhead, and this might not be acceptable in latency-sensitive applications. NanoLog operates at nanosecond granularity. NanoLog is built on a three-component system - Preprocessor/Combiner, Runtime Library, and Decompressor. The core idea is to shift work out of the runtime hot path, distributing it across compilation and post-execution phases.

Performance Bottlenecks in Traditional Logging

Traditional logging frameworks are implemented using printf or syslog and the overheads happen because of the following reasons

1. formatting log messages into human-readable strings
2. flushing and writing log messages to disk or over the network
3. to ensure thread safety, traditional logging systems often employ locks, leading to contention

Architecture Overview

NanoLog essentially breaks down the logging into the following steps - capturing log messages, serializing them into a binary format, storing them in a circular buffer, and asynchronously emitting them (via emission thread), decompressing and writing them to the final output destination. This allows the main application to proceed without waiting for log emission.

In NanoLog, this log message is serialized into a binary format, with the timestamp, symbol, and price stored as binary values. The serialization process might take just a few nanoseconds, compared to microseconds or milliseconds for traditional logging.

Preprocessor: Static Analysis and Code Generation

The preprocessor is where NanoLog innovates and takes care of several crucial tasks, like

1. analyzing NANO_LOG() statements and extracting static information at compile-time
2. inferring argument types by parsing format strings (e.g., “%d %f”)
3. generating type-specific processing code
4. replacing original logging statements with optimized code (for each log)

Each log statement is also associated with a unique identifier at compile time. This identifier, along with the values of the variables associated with the log statement, is encoded into a compact binary format. Static information for each log statement is cataloged in a dictionary entry, including file name, line number, severity level, and format string.

Thus NanoLog does not need to interpret the log message format at runtime. The compile-time knowledge allows Nanolog to encode log messages extremely efficiently, as it avoids the runtime overhead associated with string formatting. For each NANO_LOG() statement, two critical functions are generated

• record(): captures dynamic data in memory buffers.
• compact(): compresses recorded data for efficient I/O.

Runtime Efficiency

NanoLog achieves runtime efficiency through the use of lock-free implementation of circular buffers (queues). During logging, the encoded log messages are atomically appended to the buffer. By using a circular buffer, Nanolog

1. avoids the need for expensive memory allocations and deallocations
2. ensures that memory is reused efficiently, avoiding cache misses and reducing latency.

NanoLog also employs some interesting micro-optimizations, some of which are

1. each logging thread has its buffer, eliminating synchronization (shared-nothing)
2. each buffer is a single-producer, single-consumer circular queue, eradicating locks
3. private variables for logging and background threads are stored on separate cache lines.

Aligning variables on different cache lines minimizes false sharing and cache thrashing. This can be demonstrated with this quick example

#include <stdio.h>
#include <stdint.h>

#define CACHE_LINE_SIZE 64

typedef struct {
    int log_level;
    char log_file[32];
    char padding[CACHE_LINE_SIZE - sizeof(int) - 32];
} __attribute__((aligned(CACHE_LINE_SIZE))) LoggingVars;

typedef struct {
    int x;
} __attribute__((aligned(CACHE_LINE_SIZE))) ThreadVars;

typedef struct {
    LoggingVars loggingVars;
    ThreadVars threadVars;
} PrivateVars;

int main() {
    PrivateVars vars;
    
    // look at the addresses
    // it reasserts that the structures are on different cache lines
    printf("Address of logging vars: %p\n", (void*)&vars.loggingVars);
    printf("Address of thread vars: %p\n", (void*)&vars.threadVars);
    return 0;
}

The use of __attribute__((aligned(CACHE_LINE_SIZE))) attribute (called alignment modifier) ensures each structure starts at the beginning of a cache line minimizing false sharing and cache thrashing.

$ gcc main.c && ./a.out
Address of logging vars: 0x7fffd8c87400
Address of thread vars: 0x7fffd8c87440

Serialization and Encoding

NanoLog serializes log parameters into a compact binary representation. This approach has several advantages:

• faster than string formatting, reducing the time spent in the logging path
• more compact than text, reducing the memory footprint of the log buffer

By specifying log formats statically at compile time, NanoLog ensures that the correct types are used in log messages, preventing type-related bugs. Some nuances around this efficient binary log format:

1. maps Intel Time Stamp Counter (TSC) to wall time, avoiding runtime wall time conversion
2. each message is variable-sized and is designed to take up the bare minimum space
3. non-string parameters are compacted (small ints take up fewer bytes than larger ones)
4. strings are null-terminated to avoid explicit length storage

Background logging thread

Once the log messages are encoded and stored in the in-memory circular buffer, NanoLog uses a background thread to process the serialized log messages and persist them to a durable storage medium. This ensures that the critical path of execution is not blocked by I/O operations. This decouples the logging from I/O, reducing the impact of logging on the application’s performance. The thread is optimized for rapid log processing and it

1. defers the formatting and sorting to post-execution, reducing runtime overhead
2. processes buffer contents while logging threads continue to record new messages

Decompressor and Chronological Ordering

Decompressor now combines compacted data with dictionary information to produce readable logs. It restores the chronological order of the log messages by processing roughly time-ordered buffer entries.

Performance Optimizations

Traditional logging frameworks often rely on mutexes to synchronize access to shared resources, such as the log buffer. However, mutexes introduce significant latency due to contention and context switching. Nanolog uses a lock-free circular buffer for managing the in-memory log message buffer.

NanoLog also minimizes memory allocations during the logging process by pre-allocating memory for the circular buffer and reusing this memory for subsequent log messages. This avoids the performance penalties associated with dynamic memory allocation.

NanoLog’s design allows it to scale effectively across multiple cores, making it ideal for modern multicore processors.