Engineering a Fast Logger

For years, every time I had to pick a logger for my NodeJS-based applications, my choice has been Pino. I admired the work from Matteo Collina and his colleagues, so much that I applied to work at Nearform precisely because of them.

Some weeks ago, while working on a couple of web projects, I felt compelled to study Pino’s internals and see if I could reproduce its amazing performance properties in a library of my own, introducing some changes that reflected my personal preferences on API surface.

The result of these efforts is a small collection of libraries (Logtau), which I’m proud to announce that it outperforms Pino in some scenarios (Pino is quite close to being optimal, and there are plenty of tradeoffs to consider, so I wouldn’t dare to say that Logtau outperforms it in a general sense).

What follows is a short list of insights on the engineering work that has been put into developing Logtau.

1st Rule: Measure Everything, All the Time

Even though there are much more specific (and interesting) lessons that we can learn from these efforts… I think I wouldn’t have reached any of them without being relatively strict with this one.

Before continuing, a disclaimer: I’m not an expert NodeJS in any meaningful way. I don’t know “enough” about its internals, and the same could be said about its public API. This lack of knowledge and experience on this topic has shaped my approach.

Reading Pino’s code is a great way to learn many of the necessary bits, but it’s not enough. Inspecting code alone does not tell us the story behind some of their choices… and traversing the whole git (and issues tracker) histories would be a nightmare, incredibly tedious.

So, when in doubt, my approach has been writing many variants of the mechanisms at play and try to benchmark them as carefully as possible, although no single benchmark will ever be the perfect judge of what’s “better”, specially when there are tradeoffs to consider (some examples: memory vs cpu usage, latency vs throughput, stability guarantees vs avoiding data loss…)

Many times, the results for the compared options are almost undistinguishable, unless one is willing to implement more sophisticated and time-consuming experiments. In such occasions I’ve leaned towards picking the “simplest” code. This is not lazyness (well, just a little bit), but recognizing that more complex benchmarks would likely be quite fragile.

2nd Rule: Serialize at Call Time, Buffer Strings/Bytes

Many loggers are built around a log record: we call log.info(msg, obj), a record object is built, moved through a pipeline, and eventually serialized and consumed by a sink. In this scenario the record stays alive as a structured object for as long as the pipeline needs it.

Logtau serialises each record into its final text at call time, and the rest of the pipeline deals with strings/bytes, not structured objects. Pino does essentially the same, I took inspiration from it.

Winston took the structured object approach, while LogTape and Bunyan preferred a hybrid approach: serialization at call time for synchronous logging, and structured log record objects for asynchronous logging.

While this choice might seem inconsequential, it’s probably among the most relevant architectural decisions in the whole library. Once a record exists as a string, nothing about the caller’s objects matters anymore. A sink can easily buffer the strings it receives to minimise the mount of syscalls it has to make and maximise throughput.

But what happens when we try to buffer record objects? If we defer the serialisation, then we have a correctness problems in our hands: the caller can mutate that objecft after the log call returns. To be safe we must deep-clone it before we return control to the caller, or serialize eagierly anygway. The deep clones not only increase how much memory we use, but also increase the pressure on the garbage collector.

This is why logtau’s Sink interface takes strings, not records:

export interface Sink {
  write(line: string): void
  flush(): Promise<void>
  flushSync(level?: LogLevel): void
  close(): Promise<void>
}

All the “interesting” work (serialization, redaction, error shaping) happens before the string reaches the sink.

The Hot Path, Dissected

In our case, the “hot path” is the code that runs on every single log call. If we want our logger to be fast, this is the code that matters most. Every branch, every allocation, every property lookup that we can move out of it is a win.

Disabled levels cost nothing

The first thing any logger must decide is whether a given call is even enabled. If our logger is at info level, log.debug(...) should be as close to free as possible, because debug calls are everywhere and most of them are disabled in production.

The simplest implementation is a per-call check:

if (severity < threshold) {
    return
}

This is cheap, but not free. Logtau removes the branch entirely by resolving each level method once, at construction time. When we build a logger, every level method is set to either a real dispatcher, or a singled shared no-op function, depending on the configured threshold:

const noop: LogMethod = () => {
  // Disabled at construction; no per-log work.
}

const proto: Logger = {
  debug:    LEVEL_SEVERITY.debug    < threshold ? noop : dispatchDebug,
  info:     LEVEL_SEVERITY.info     < threshold ? noop : dispatchInfo,
  warn:     LEVEL_SEVERITY.warn     < threshold ? noop : dispatchWarn,
  error:    LEVEL_SEVERITY.error    < threshold ? noop : dispatchError,
  critical: LEVEL_SEVERITY.critical < threshold ? noop : dispatchCritical,
  fatal:    LEVEL_SEVERITY.fatal    < threshold ? noop : dispatchFatal,
  with: withMethod,
  child: withMethod,
}

With this approach, a disabled log.debug is a no-op function, we avoid having to access two variables, perform a comparison, and branch. We also avoid these operation for the enabled log calls, but the relative gains are very hard to measure in that case.

I’m not really sure about the performance effects of branching in NodeJS, because it’s a fairly complex beast, but I suspect it might be a similar case to what we have in “low level” code, for which branching can disrupt CPUs instructions pipelining, which in turn can lead to a lot of wasted CPU work and performance degratation.

In my micro-benchmarks for the disabled logs, I measured ~0.65ns saved per call, but it’s likely that I might have accidentally primed the CPU’s branch predictor, so the difference in real scenarios is probably a bit bigger.

Per-Level Formatters with Prefix baked in as a Literal

What about the enabled path? Every log line has the same structure:

{"level":"info", "time": 2132156387, "msg": "Something Something..."}

How should we generate this simple string? My first impulse was to rely on JSON.stringify, after all, it’s a highly optimized function and it would be very hard to beat. That’s actually the case… if we were talking about arbitrary shaped objects, but luckily for us, we can do better.

Pino does the smart thing here, and that’s what I copied after first being surprised and then convinced after having executed my own benchmarks:

• First, given that we always have the same structure, we can rely on template literals or concatenation to construct that log line. Important: the gain we have here is NOT because template literals or concatenation are faster than JSON.stringify, but because we don’t have to build the object that this function consumes.
• Second, because the level property is tied to the specific log method (debug, info, warn, error, …), we can also pre-compute that part instead of performing variable substitution each time.

function makeLevelFormatter(level, serializerEntries, renderBody) {
  // Built ONCE per level. The prefix is now a literal.
  const prefix = `{"level":"${level}","time":`

  return (time, msg, fields, bindings = '') => {
    const head = `${prefix}${time},"msg":${quoteString(msg)}`
    if (fields === undefined) {
      return `${head}${bindings}}`
    }
    // ... serialize fields into `body` ...
    return `${head}${bindings},${body.slice(1)}`
  }
}

Here you can see the results of some micro-benchmarks:

“Harcoding” the level offers us a performance improvement that ranges between 0.3% and 2.2% (refining the interval would take too much of my time).

Some of you, if you are familiarized enough with how V8 works, might be thinking that I left out an intersting option:

• To have a pre-build object and replace some of its fields every time that we have a log call. This way we could take advantage of JSON.stringify without having to pay the price of constructing a new object each time… right?

Well, that is indeed an interesting idea. And I can tell you already that the performance results are good. However… it doesn’t scale well when we introduce arbitrary fields/objects in our log records. It’s not trivial to remove the fields created in previous calls, even less doing that in a performant way.

Monomorphisation: Keeping V8’s Inline Caches Happy

When V8 runs our JavaScript, it does not treat objects as loose bags of properties. Each object is assigned a hidden class (V8 calls it a Map; other engines call it a Shape) that describes its exact layout: which properties exist, in which order, at which memory offsets.

Property accesses like this._bindingFragment compile to inline caches (ICs): the first time the access runs, V8 records “objects of this hidden class store _bindingFragment at offset N” and the next access is a couple of machine instructions.

Now… This is only fast when the same access site sees a stable hidden class. If one logger has shape A and another has shape B, the IC at this._bindingFragment becomes polymorphic; see enough shapes and it goes megamorphic and falls back to a slow dictionary lookup. The same thing happens if you ever use an object as a hash map: adding and deleting keys dynamically tips it into “dictionary mode”, which is dramatically slower for reads.

Logtau is built so that every logger has exactly one hidden class. The level methods live on a shared prototype, and every instance carries the same single own property, _bindingFragment, added the same way:

function withMethod(this: DerivedLogger, bindings: LogFields): Logger {
  const part = formatter.bindingFragment(bindings)
  const inst = Object.create(proto) as DerivedLogger
  inst._bindingFragment = this._bindingFragment + part
  return inst
}

Here we use Object.create(proto) to give the child logger the same prototype (so method dispatch is monomorphic), and the single _bindingFragment write gives it the same shape as every other logger. The result is that the hot path’s property reads never deoptimize, no matter how many child loggers we spin up.

Not strictly related to our logger, but if you want to take some general lessons with you:

• Keep the shape of your “hot” objects stable
• Initialize all fields in the constructor, in the same order
• Do not use the delete operator to remove fields from your objects
• Do not use regular objects to implement dictionaries (we have Map for that)

Serialization: The Price of Replacing JSON.stringify

As I already mentioned (and you could also guess by yourself), JSON.stringify is a pretty performant function. In most situations it makes no sense trying to replace it with anything that we could code by hand in pure JavaScript.

Unfortunately, we have some complications to account for. JSON.stringify is unable to deal with these 2 cases:

• circular references
• unserializable properties (like functions, or bigint values that have no representation in JSON values)

My approach to avoid having to pay for our handcrafted serialization function every time is to use it only as a fallback:

export function serializeForLog(value: unknown): string {
  try {
    return JSON.stringify(value) ?? 'null'
  } catch {
    return serializeValue(value) // bigint, circular refs, etc.
  }
}

For the 99% of log payloads that are plain JSON-friendly objects, we get almost native speed (plus the extra call overhead).

An interesting case that is worth mentioning is errors serialization. By default, JSON.stringify converts Error objects into {}. We could use our handcrafted serializer for it, but that would impact otherwise JSON-friendly objects that could have gone through the fast path. Because of this, we always place errors in a predefined key (err) and pre-serialize them before passing the data to the general serializer, so calls such log.error('crash!', { err }) stay on the fast path.

A Custom String Escaper - But Only Sometimes

Every JSON string has to be quoted and escaped. As before, we could be using JSON.stringify for this, but every call has a relatively stable overhead of roughly ~35 nanoseconds (in my computer). This leads us to think that there might be a length threshold under which it is cheaper to perform the calculations in pure JavaScript instead of passing the ball to the engine’s optimized functions.

My experiments showed that 16 is a pretty good threshold to choose between the natively optimized functions, and our own custom implementatons (which are slower but don’t have to pay for the 35ns overhead). The threshold also accounts for the overhead introduced by the extra checks.

const SHORT_MAX_LENGTH = 16

export function quoteString(value: string): string {
  if (value.length <= SHORT_MAX_LENGTH) {
    let escaped: string | null = null
    let runStart = 0
    for (let i = 0; i < value.length; i++) {
      const code = value.charCodeAt(i)
      if (code >= 0x20 && code !== 0x22 && code !== 0x5c) {
        continue // ordinary char, nothing to do
      }
      // ... rare: build the escaped output ...
    }
    if (escaped === null) {
      return `"${value}"` // common case: nothing needed escaping
    }
    // ... assemble escaped result ...
  }

  // Longer strings: one regex test, fall back to native only if needed.
  if (!NEEDS_ESCAPE.test(value)) {
    return `"${value}"`
  }
  return JSON.stringify(value)
}

For a short string with nothing to escape (by far the most common case) the whole function is a tight charCodeAt loop that finds no special characters and returns `"${value}"` directly. No call overhead, no allocation beyond the result. For longer strings, a hand-written loop stops winning (the native escaper’s per-character work is faster in bulk), so logtau does a single regex test and only calls JSON.stringify when escaping is actually required.

I find this is an interesting example of why measuring and benchmarking all the time is extremely important. The choices and thresholds are not obvious, the code is arguably ugly, clearly not something that anyone would write because they thought it was obvious or better. I had to have a very strong reason to write this complicated function.

Bindings and Child Loggers: Paying the Cost Once

This is a sort of repetition of an idea that we already introduced, to pre-compute some “fragments” of the values we’ll be dealing with.

Structured loggers let us derive a child that carries extra context (log.with({ requestId })), so every log line from that child includes the binding.

A naive implementation would merge the bindings into the fields object on every log call. We just precompute the corresponding _bindingFragment, essentially moving work from the log call to the logger setup.

Backpressure: How a to Handle Stalled Pipes/Sockets

When writing to pipes or sockets, it is possible to get EAGAIN errors. This essentially happens because the kernel-side buffer is full, which in turn is usually caused by slow readers on the other side of the socket/pipe.

If you are passionate enough about UNIX-related technicalities, it might be worth reading about how EAGAIN, EWOULDBLOCK, EINTR, O_NONBLOCK relate to each other and under which conditions they might happen. In any case, for the sake of my own sanity, I’ll go ahead and continue writing about the logger.

Once we receive an EAGAIN error, we can deal with it in many ways, of which the most obvious two are:

• Retry immediately, in a tight loop. We recover the instant the buffer drains, which is “perfect” for a short burst that clears in microseconds… But if it were to take more than that, we would peg a CPU core at 100% for the time that the kernel buffer is full.
• Sleep a fixed interval, then retry. In this case we don’t risk burning our CPU, but our recovery latency is at least the interval we have set. So, we loose reactivity.

The fun part is that we cannot know in advance which kind of stall we are in, a sub-millisecond hiccup or a multi-second outage.

Pino’s answer to this problem is a sleep using a fixed interval (BUSY_WRITE_TIMEOUT = 100, 100 milliseconds). On every EAGAIN it waits 100ms and retries, “forever”, with no retry cap (its behavior can be modified by using the retryEAGAIN escape hatch, but I’m talking about the default). This approach is simple and robust, and it doesn’t cause CPU usage spikes. But common cases of backpressure events (very short transient bursts) cost a minimum of 100ms.

Logau’s approach differs depending on whether it’s logging asynchronously or synchronously. The differences are rooted on whether the caller can yield the event loop or not.

The synchronous drain (used by the auto-flush inside write, by flushSync, and the exit listener) cannot yield. In that case it busy-spins, retrying immediately, but if it reaches a the deadline (10ms), it throws an error.

let inStall = false
let deadline = 0n
// ...on each EAGAIN:
if (!inStall) {
  deadline = process.hrtime.bigint() + SYNC_EAGAIN_BUDGET_NS // 10 ms
  inStall = true
} else if (process.hrtime.bigint() > deadline) {
  throw new EagainBudgetExceededError(/* ... */) // give up — buffer is retained
}
continue // otherwise retry now

The budget is 10 ms, measured from the first EAGAIN of a stall and reset the moment any byte goes through, so a recovered-then-stalled-again sequence gets a fresh budget each time. If the 10 ms elapses with no progress it throws, but it keeps the unwritten buffer, so a later flush gets another attempt and no logs are lost to the give-up itself. Ten milliseconds sits comfortably above the sub-millisecond transient bursts that are the realistic case, and comfortably below the point where a human notices lag.

In case you want a better reference on under which circumstances an error would be thrown, the throughtput should be below 0.1KB/s for more than a second for that to happen.

Going back to the asynchronous case, the asynchronous drain, which returns a promise and is awaited, can yield. In that case I introduced an adaptive behavior:

let eagainCount = 0
// ...on each EAGAIN:
if (eagainCount < ASYNC_TIGHT_YIELDS) {            // first 1024
  eagainCount++
  await new Promise(r => setImmediate(r))          // retry on the next loop turn
} else {
  eagainCount++
  await new Promise(r => setTimeout(r, ASYNC_ESCALATION_MS)) // 10 ms
}
// ...and on any successful byte:
eagainCount = 0

First, it busy-spins for the first 1024 iterations, and if after that we are still getting EAGAIN errors, it moves to a less aggressive strategy, sleeping the same way as Pino, but with shorter timeouts (10ms instead of 100ms).

This allows us quickly clearing short bursts, achieving low latency, but at the same time avoids being overly aggresive during longer spans of time, to avoid unnacceptable CPU usage spikes. Crucially, the counter resets to zero on any successful write, so a pulsed workload (bursts separated by brief recoveries) keeps getting the fast, aggressive treatment instead of being stuck in the slow 10 ms cadence after one bad patch.

And because the async path never blocks, it needs no hard cap at all: the event loop stays alive throughout, so the application keeps control. It can race the flush against a timeout, handle a signal, or exit. The host is never “blocked”, which is the very thing the sync budget exists for.

Some Benchmark Results

All the results I’ll present here can be found in Logtau’s repository, in the bench-vs-pino package, so if you want to review you can do it. I think it’s interesting to have more eyes on it, because I might have made mistakes while running the experiments.

Async per-log latency

Notice the pattern: the wider the log call, the smaller the gap. Pino’s advantage-eraser is its large fixed per-call overhead; as the payload grows, that fixed cost becomes a smaller fraction of the total, and the ratio shrinks from 12.8x toward 2.7x. The places Logtau wins biggest are the cheap, high-frequency calls… Which, conveniently, are most of them.

Sync per-log latency

Here the results not really interesting. Logtau still retains a small advantage (~1.5x), but nothing specially amazing.

Other Notes

While benchmarking, I made many mistakes that took me many days to notice, with varying degree of relevance… and I’m still unsure about having been abble to get rid of all the main methodological mistakes.

Some of the things that took me to much time to fix:

• Setting attributes like the PID into the log lines to ensure a fair comparison against Pino.
• Forcing yields every N loop steps to ensure that Pino would flush (it does under different circumstances than Logtau).

I haven’t said anything about the off-thread workers yet… I think that topic requires its own individual article, as this one is already quite long.

I hope you found this interesting, and it would be awesome if I convinced you to try Logtau too (WARNING: it still does not have some “serious” features such as OTEL support, but the Logau libraries collection is improving at good pace).

Well, thank you for reading me, that’s it for today!