The problem

While building fastbook, a personal C++23 project, I ran into the following problem. I wanted to add logging to the path that runs on the hot-thread, in order to later be able to trace what the program did, for reproducibility and debugging.

This sounds like a simple task, right?

#define LOG(fmt, ...) \
    std::println(file, "[DEBUG] {}:{} " fmt, __FILE__, __LINE__ __VA_OPT__(,) __VA_ARGS__)

// At the call site:
LOG("Received update for instrument {}: {}", instr, price);

If this runs on a hot path, meaning code that runs millions of times per second and whose latency you care about, you are dead. Let’s analyze why.

When you call std::println, std::ostream::operator<<, fprintf() or similar functions, you pay the following costs:

  • The format string is parsed on every call, to find the replacement fields.
  • Every argument has to be converted to text. Depending on the implementation, this can be expensive, since it may involve heap allocations on top of the parsing above. Floating-point values are especially costly.
  • The resulting text is copied into the stream’s buffer (streams are fully buffered for regular files).
  • When the buffer fills up (or on std::endl / fflush()), its contents are passed over to the kernel with a write() system call, which copies them into the page cache. Worse, with O_DIRECT or an fsync(), the call also pays the cost for a full-blown disk access.

stderr and std::cerr are worse, because they are unbuffered by default, so every call reaches the kernel.

On my benchmark machine (see Results), one such call costs 3,000 to 7,000 cycles at the median, and 15,000 to 60,000 cycles at the 99th percentile.

On a system with a latency budget in microseconds, that is not acceptable. However, being able to log is sometimes extremely helpful, for the reasons mentioned above. So how can we log without killing performance?

The design

The following approach is based on three principles.

  • Do as much computation as possible at compile time. The format string, __FILE__, __LINE__ and the log level are all known at compile-time, so there is no reason to parse and copy them at runtime. For every LOG call site, the compiler builds one constant metadata object that holds them, together with a function generated just for that call site, which turns the logged values into text. This object lives in the binary’s read-only data. At run time, the hot thread stores only a pointer to it.

  • Move the expensive part to another thread. Formatting, system calls and I/O all happen on a background thread whose latency does not matter. The hot thread pushes the minimum needed to reproduce the line later: a pointer to the metadata object, a timestamp, and the bytes of the argument. Nothing else. Communication between the threads is achieved by using a lock-free single-producer/single-consumer (SPSC) ring.

  • Never block (mutex/lock, I/O), and do the minimum that is required for synchronization. Each thread owns its own ring, so hot threads never contend with each other: no communication, no locks, no cache-line ping-pong. Publishing a record costs one store with release ordering. If the ring is full, the record is dropped and counted, and the background thread reports the drops. And this is the trade-off we make here: It is better to miss a log once in a while rather than pay the latency cost once in a while.

Implementation

A simplified version of the code, starting with the data.

// Formats one record's payload. Generated at compile time for each call site.
using FormatFn = void (*)(const std::byte *payload, std::string &out);

// Describes one LOG call site. Built once, at compile time.
struct LogMetadata {
  const char *fmt, *file;
  uint32_t line;
  Level level;  // DEBUG, INFO, ERROR, etc.
  FormatFn fn;
};

// Written on every LOG call, at run time.
struct RecordHeader {
  const LogMetadata *meta;
  uint64_t tsc;  // timestamp counter at the time of the call
};

struct Record {             // 256 bytes, fixed size
  RecordHeader hdr;
  std::byte payload[PAYLOAD_BYTES];  // raw argument bytes, strings are encoded with their length as prefix.
};

using LogRing = SPSCQueue<Record, LOG_RING_SIZE>;
std::array<LogRing, N_THREADS> rings;  // one ring per thread

thread_local LogRing *my_ring;  // this thread's ring (producer side)

What the hot thread does:

// One constant per call site, built by the compiler.
#define LOG(lvl, fmt, ...)                                          \
  do {                                                              \
    static constexpr LogMetadata meta{                              \
        .fmt = fmt, .file = __FILE__, .line = __LINE__,             \
        .level = lvl, .fn = decoder_for<fmt, ArgTypes...>};         \
    emit(&meta, __VA_ARGS__);                                       \
  } while (0)

// The only run-time work: reserve a slot, fill it in place, publish it.
template <class... Args>
void emit(const LogMetadata *meta, Args &&...args) {
  Record *rec = my_ring->try_reserve();  // a free slot, or nullptr if the ring is full
  if (!rec) {
    dropped++;                           // never block: drop, count, report later
    return;
  }
  rec->hdr.meta = meta;                  // pointer to the compile-time constant
  rec->hdr.tsc = __rdtsc();              // a few cycles
  write_args(rec->payload, args...);     // memcpy()s of known size, compiled down to a few mov instructions
  my_ring->commit();                     // publish: one release store
}

void hot_thread() {
  while (true) {
    // process market data...
    LOG(INFO, "Received update for {}: {}", instr, price);
  }
}

decoder_for<fmt, ArgTypes...> is where the compile-time work happens. For a given format string and argument types, the compiler splits the format string, checks that the number of {} matches the number of arguments, and generates a function that reads each argument back from the payload and generates the final output string. Nothing about the format string is parsed at run time.

What the background thread does (again simplified):

bool drain_and_log() {
  std::vector<Record> records;
  for (auto &ring : rings) {
    drain_ring(ring, records);           // pop everything that is there right now
  }
  sort_by_timestamp(records);            // merge the per-thread streams

  std::string out;
  for (const Record &rec : records) {
    rec.hdr.meta->fn(rec.payload, out);  // format with the generated decoder
  }
  print_to_file(outfile, out);           // one write() per pass, not per line

  return !records.empty();
}

void logger_thread() {
  while (!stop.load(std::memory_order_acquire)) {
    if (!drain_and_log()) {
      std::this_thread::sleep_for(std::chrono::milliseconds(1));
    }
  }
}

Results

Each call was timed using rdtscp. The numbers are medians over 5 runs. Every contender writes the same line to the same file, except std::format_to, which only formats into a string and does no I/O.

Cost of one log call on the hot thread, in cycles

A log call costs about 70 cycles at the median, and under 600 cycles at p99. That is about 45× faster than only formatting the line with std::format_to, and about 95× faster than a plain write() for a formatted line.

The work did not disappear. Formatting and I/O still happen, but on the background thread, so the hot-thread is not affected at all.

Full code: fastbook