Pino and Serilog, Measured: The Async Sink Is Fast Because It Drops Lines

Aurora Coffee Co.'s checkout writes a structured log line for every order. I wanted to know what that costs, so I logged the same event 200,000 times through every sink configuration I could think of, on Node 24 and on .NET 10. Two lines of the Serilog run:

serilog -> compact JSON, sync           164 k/s  mean   6081 ns  p50  4500  p99  28400  max 46985500
serilog -> compact JSON, async          331 k/s  mean   3017 ns  p50  1000  p99   4000  max 19268600

Wrapping the sink in WriteTo.Async doubled throughput and cut the p99 by a factor of seven. That is the result everyone quotes, and it is the reason the async wrapper is in nearly every Serilog configuration I have ever read.

Then I counted the lines that reached the file:

file                   lines        bytes   bytes/line   expected lines
serilog-async.log       80256   21,047,885          262           202000   <-- MISMATCH
serilog-json.log       202000   53,009,780          262           202000

121,744 log lines did not exist. No exception, no warning, no counter anywhere in the application. The async sink was twice as fast because it was doing a little over a third of the work.

This post is what the rest of that benchmark found: what structure actually costs (less than you think), what the sink costs (more than you think), and which of the two defaults in front of you is quietly lossy.

The setup, so the numbers mean something

Every number below comes from one harness per runtime, logging the same event — an order with five fields — 200,000 times after a 2,000-iteration warm-up. Each call is timed individually with process.hrtime.bigint() on Node and Stopwatch.GetTimestamp() on .NET, so the tail is real rather than derived from a total.

Two details matter more than they look.

The loop yields. My first Node run had the buffered sink coming out slower than the synchronous one, which is impossible. The cause was the benchmark, not the sink: a tight synchronous loop never returns to the event loop, so a buffered destination can never drain and simply accumulates — 40MB of it. Yielding every 1,000 iterations fixed it. If your logging benchmark shows buffering making things worse, this is why.

The line counts are verified. Every harness finishes by counting the lines in each file and comparing against what it logged. That check is the only reason this post exists; without it, the Serilog async result reads as a clean win.

// bench.ts — the shape of each measurement
const N = Number(process.argv[2] ?? 200_000);
const WARMUP = 2_000;
const YIELD_EVERY = 1_000;

const tick = () => new Promise<void>((resolve) => setImmediate(resolve));

async function measure(name: string, run: (i: number) => void, flush?: () => void): Promise<void> {
  for (let i = 0; i < WARMUP; i += 1) run(i);
  await tick();

  const samples = new Float64Array(N);
  let busy = 0;
  for (let i = 0; i < N; i += 1) {
    const t0 = process.hrtime.bigint();
    run(i);
    const dt = Number(process.hrtime.bigint() - t0);
    samples[i] = dt;
    busy += dt;
    // Without this the event loop never runs and a buffered sink cannot drain.
    if (i % YIELD_EVERY === YIELD_EVERY - 1) await tick();
  }
  flush?.();

  const sorted = Float64Array.from(samples).sort();
  const at = (q: number) => sorted[Math.min(sorted.length - 1, Math.ceil(q * sorted.length) - 1)];
  const mean = samples.reduce((a, b) => a + b, 0) / samples.length;

  console.log(
    `${name.padEnd(36)} ${(N / (busy / 1e9) / 1000).toFixed(0).padStart(6)} k/s  ` +
      `mean ${mean.toFixed(0).padStart(6)} ns  p50 ${at(0.5).toFixed(0).padStart(5)}  ` +
      `p99 ${at(0.99).toFixed(0).padStart(6)}  max ${at(1).toFixed(0).padStart(8)}`,
  );
}

Hardware is a laptop, not a server, so read the ratios rather than the absolute rates.

---

What structure actually costs

The fear is that JSON serialization is expensive compared to writing a string. Here is the Node run, all six configurations, verbatim:

node v24.16.0   pino 10.3.1   N=200000 (+2000 warm-up)

string concat, writeSync                211 k/s  mean   4733 ns  p50  3700  p99  16400  max  1070300
pino, sync destination                  193 k/s  mean   5181 ns  p50  4400  p99  19400  max  1035400
pino, buffered destination              176 k/s  mean   5694 ns  p50  5100  p99  18700  max   931400
debug at level=info, plain payload    12068 k/s  mean     83 ns  p50   100  p99    300  max   263800
debug at level=info, costly payload     100 k/s  mean  10047 ns  p50  7900  p99  26400  max  1240800
debug guarded by isLevelEnabled       10295 k/s  mean     97 ns  p50   100  p99    300  max    56300

file                   lines        bytes   bytes/line   expected lines
pino-buffered.log      202000   41,091,780          203           202000
pino-quiet.log              0            0            0                0
pino-sync.log          202000   41,091,780          203           202000
text-sync.log          202000   22,709,780          112           202000

all files complete

Structured logging costs 9%. 5,181ns against 4,733ns for building the equivalent string by hand and writing it to the same file descriptor. That is the entire serialization penalty, and it buys you a line a machine can filter instead of one a regex has to guess at.

The .NET side is less flattering and more interesting:

string interpolation, AutoFlush         302 k/s  mean   3313 ns  p50  2600  p99  13200  max   695200
serilog template -> text file           127 k/s  mean   7888 ns  p50  5700  p99  31000  max  3345300
serilog -> compact JSON, sync           164 k/s  mean   6081 ns  p50  4500  p99  28400  max 46985500

Serilog's text sink is slower than its JSON sink — 7,888ns against 6,081ns. Rendering a message template into a human sentence costs more than emitting the structured document, because rendering means formatting every property into the middle of a string, while the JSON formatter writes the values where they already are. The readable format is the expensive one. If you have been keeping a text sink because JSON "must be heavier", that is backwards.

What is not free is the bytes:

	bytes per line	relative
text, Node	112	1.0×
JSON, Node (pino)	203	1.8×
text, .NET	117	1.0×
rendered template, .NET	176	1.5×
compact JSON, .NET (Serilog)	262	2.2×

That is the real bill, and it is not CPU. At a thousand lines a second, pino's extra 91 bytes per line is 7.9GB a day of storage and ingest you did not have before — 86.4 million lines times 91 bytes. Every hosted log product prices on exactly that number.

---

The sink, where the actual money is

A logger does two things: turn an event into bytes, and get those bytes somewhere. The first is what benchmarks measure. The second is what wakes you up.

Synchronous

The write happens on the calling thread. Your request waits for the disk. On a local SSD with the page cache in front of it that is usually fine — and sometimes it is not:

serilog -> compact JSON, sync           164 k/s  mean   6081 ns  p50  4500  p99  28400  max 46985500

The mean is 6µs. The maximum is 47 milliseconds, for a single log call. That is one request, somewhere in those 200,000, that spent a twentieth of a second inside Log.Information. Nothing in the code is slow; the operating system decided to flush, and the caller paid for it. Synchronous sinks put the storage tail onto your request tail, and a mean will never show it to you.

Buffered, Node style

Pino's buffered destination hands the bytes to an internal buffer and returns. I pointed it at a sink that takes 2ms per flush — a loaded log shipper, a network volume, a disk under pressure — and logged 20,000 lines:

sink: 2ms per flush, 20000 lines logged
  caller p50           1900 ns
  caller p99          14500 ns
  caller max        1071900 ns
  flushes done             21
  RSS at start         57.5 MB
  RSS peak             73.7 MB
  RSS growth           16.2 MB

The caller never waited — a p50 of 1.9µs against a sink taking two milliseconds per flush. Twenty-one flushes completed in the time it took to log twenty thousand lines, and resident memory grew 16.2MB. The backlog did not disappear; it is sitting in the heap waiting for a sink that is not keeping up.

This is the trade, stated plainly: a buffered sink does not make the write cheaper, it makes the write someone else's problem later, and "later" is held in your process memory. If the sink stays slow, you do not get a latency alert. You get an out-of-memory kill, which is a much worse way to find out.

And when the process dies

The reason you are logging at all is usually that something went wrong. So I logged 50,000 lines to a buffered pino destination and killed the process the way processes actually die — no flush, no shutdown handler:

lines logged       50000
lines on disk          1
lost               49999  (100.0%)

One line. The buffer is in the dead process's memory, and the file has what happened to be flushed before it died. A process.on('exit') handler calling flushSync() closes most of this, and SIGKILL and a hard crash close it right back open.

Asynchronous, .NET style

WriteTo.Async puts a bounded queue and a background thread between your code and the sink. The default queue is 10,000 events, and the default behaviour when that queue is full is to drop. Here are all three Serilog sink configurations side by side, from the same run:

serilog -> compact JSON, sync           164 k/s  mean   6081 ns  p50  4500  p99  28400  max 46985500
serilog -> compact JSON, async          331 k/s  mean   3017 ns  p50  1000  p99   4000  max 19268600
serilog -> JSON, async blockWhenFull    122 k/s  mean   8220 ns  p50  3700  p99  38700  max 23037300

And the line counts for those three files:

serilog-async-block.log   202000   53,009,780          262           202000
serilog-async.log          80256   21,047,885          262           202000   <-- MISMATCH
serilog-json.log          202000   53,009,780          262           202000

Read those two blocks together and the picture inverts:

configuration	throughput	lines kept
sync	164 k/s	202,000
async, default	331 k/s	80,256
async, blockWhenFull: true	122 k/s	202,000

The async sink that keeps your data is slower than having no async sink at all. 122 k/s against 164 k/s — the queue, the hand-off and the context switch cost more than they save once you stop letting it discard the overflow. The configuration everybody copies is the middle row, and the middle row lost 60% of the events.

One honest caveat on that number: this benchmark hammers the logger in a tight loop, far harder than a real service ever will, so a production queue drains between requests and drops nothing most of the time. The point is not "60% of your logs are missing". The point is that the drop is silent and unmeasured, so the one time it matters — an incident, a retry storm, the burst you most want logged — you will not know it happened. If you run WriteTo.Async, set blockWhenFull: true and accept the latency, or wire up its monitor callback so the queue depth is a metric you can see.

---

Levels: the call you thought was free

A disabled log call still evaluates its arguments. The object is built, the string is interpolated, the stack is captured — and only then does the logger decide to throw it away.

How much that costs depends entirely on the payload, and the two cases are four orders of magnitude apart:

debug at level=info, plain payload    12068 k/s  mean     83 ns   (pino)
debug at level=info, costly payload     100 k/s  mean  10047 ns   (pino)
debug guarded by isLevelEnabled       10295 k/s  mean     97 ns   (pino)

debug at Information, plain payload   37351 k/s  mean     27 ns   (serilog)
debug at Information, costly payload     77 k/s  mean  12981 ns   (serilog)
debug guarded by IsEnabled            55574 k/s  mean     18 ns   (serilog)

With a plain object, a discarded debug call costs 83ns on pino and 27ns on Serilog — free, for any purpose. Guarding it with isLevelEnabled changes nothing; pino comes out at 97ns guarded versus 83ns unguarded, which is noise in the wrong direction.

With a payload that costs something to build — here a captured stack trace — the same discarded call costs 10,047ns on pino and 12,981ns on Serilog. That is twice the price of an enabled log line that actually gets written. Guarded, it drops to 97ns and 18ns.

So the advice "always guard your debug calls" and the advice "never bother, the logger is fast" are both wrong, and the rule is mechanical:

Guard a disabled-level call when, and only when, building its arguments does real work. A serialized object, a JSON.stringify, a stack trace, a database lookup for a friendly name, a string.Join over a collection. If the payload is fields you already have, the guard is clutter.

The .NET numbers come with an extra note: Serilog's message templates mean the formatting is deferred automatically, which is why its plain-payload case is three times cheaper than pino's. What is not deferred is the argument expression itself. Log.Debug("{Trace}", new StackTrace().ToString()) builds the stack trace whether or not anybody wants it.

---

Redaction, which is where the PII went

The entire value of structured logging is that you log the object instead of a sentence about it. Which means that sooner or later you log the customer:

{"customer":{"id":"cus-5521","email":"[e-mail]","phone":"[phone]","address":{"line1":"Reparto San Juan 120","city":"Managua","country":"NI"}},"payment":{"brand":"visa","last4":"4242","token":"tok_live_9f2b61ac"}}

Pino's redact option takes paths and either censors or removes them. I measured four configurations against the same nested payload:

no redaction                          119 k/s  mean  8406 ns  p99  24900
redact: 4 paths, censored             137 k/s  mean  7284 ns  p99  19800
redact: 4 paths, removed              100 k/s  mean 10032 ns  p99  31000
redact: wildcard on two objects       110 k/s  mean  9120 ns  p99  26700

Censoring is faster than not redacting at all — 7,284ns against 8,406ns — because [redacted] is shorter than an address, so there is less JSON to write. Redaction is not a cost you are weighing against safety. It is free, and in the common case it is negative.

remove: true is the slower option at 10,032ns, because deleting keys costs more than overwriting values. Prefer censoring unless an empty key would break a downstream parser.

And then the trap, which is why the output of each configuration is worth printing rather than trusting:

redact-paths.log
  customer: {"id":"cus-5521","email":"[redacted]","phone":"[redacted]","address":"[redacted]"}
  payment : {"brand":"visa","last4":"4242","token":"[redacted]"}
redact-wildcard.log
  customer: {"id":"[redacted]","email":"[redacted]","phone":"[redacted]","address":"[redacted]"}
  payment : {"brand":"[redacted]","last4":"[redacted]","token":"[redacted]"}

The wildcard version — customer.* and payment.*, the configuration you write when you are in a hurry and want to be safe — redacted customer.id and payment.last4 as well. Those are not PII; they are the two fields that make the log line useful. A support engineer can find an order with cus-5521. They cannot find anything with [redacted].

Name the paths. On the .NET side the equivalent is a Destructure.ByTransforming<T>() policy on the logger configuration, which has the same property: be specific, or you will erase your own correlation keys.

---

The fields worth agreeing on

None of this matters if two services call the same thing by different names. Queries across services are the whole point, and they break on vocabulary, not on volume. The short list that earns its place:

• service and version — which deployable, and which build. The second one answers "did this start with the release?" without a guess.
• trace_id and span_id — the join to your traces. Both loggers attach them automatically under OpenTelemetry; the previous post in this thread covers the wiring and the loader hook that silently prevents it.
• A normalized level — the two loggers disagree about it twice over, which is the next section.
• One domain identifier per event — order_id, not id. A field called id in four services is four different things in one index.
• error.type and error.stack as separate fields, never a formatted string. The type is what you group by; the stack is what you read afterwards.

The level field is worse than a naming disagreement

Logging an info and a warning through each library, and reading back what landed. Pino's base is set to the deployable rather than left at its default, which is the first fix below and also keeps the machine's hostname out of every line:

{"level":30,"time":1790954578827,"service":"checkout","version":"2.4.1","orderId":"ord-1","msg":"info line"}
{"level":40,"time":1790954578828,"service":"checkout","version":"2.4.1","orderId":"ord-1","msg":"warn line"}

{"@t":"2026-10-02T15:16:23.5838758Z","@mt":"info line {OrderId}","OrderId":"ord-1"}
{"@t":"2026-10-02T15:16:23.6023060Z","@mt":"warn line {OrderId}","@l":"Warning","OrderId":"ord-1"}

Pino writes a number. Serilog writes a name. That much is a mapping table at the collector.

The part that catches people is the first Serilog line: there is no @l at all. Compact JSON omits the level when it is Information, because that is the implicit default. So a dashboard filtering level = "Information" returns nothing from your .NET services — not few results, none — while level >= 40 returns nothing from the Node ones. Normalize both at the collector, and treat a missing level field as Information rather than as unparseable.

Agree on those six and you can ask a question across the whole fleet. Skip it and you have a very fast way to produce JSON nobody can query.

---

When to reach for what

Log structured from the first line of a new service. It costs 9% on Node and is actually cheaper than rendered text on .NET. There is no threshold at which it starts being worth it; there is only the migration you will have to do later.

Keep the sink synchronous until you have measured that it hurts. It is the only configuration that cannot silently lose data, and on a local disk its mean is single-digit microseconds. Trade that away deliberately, not by copying a configuration snippet.

If you go async, make the loss visible. blockWhenFull: true in Serilog, a flush on exit in Node, and the queue depth as a metric. An async sink without a dropped-events counter is a system that lies to you under exactly the load you care about.

Do not log at debug in production and rely on the level to save you — it only saves you from the write, not from building the payload. Guard the expensive ones.

Rule of thumb: the cost of structured logging is bytes, not CPU. Budget storage, measure the sink, and never let a buffer be the only copy of something you needed.

---

Key Takeaways

• Structure costs about 9% of CPU and 1.8× the bytes. On .NET, Serilog's JSON sink is faster than its rendered-text sink — 6,081ns against 7,888ns — so the human-readable format is the expensive one.
• WriteTo.Async doubled throughput by dropping 121,744 of 202,000 lines. Its default is to discard on a full queue, silently. With blockWhenFull: true it keeps everything and runs slower than no async wrapper at all.
• A buffered sink moves the cost into your heap. Against a 2ms sink, the caller stayed at 1.9µs while RSS grew 16.2MB — and a hard exit left 1 of 50,000 lines on disk.
• A disabled debug call is free with a plain payload (83ns) and costs more than a real log line with an expensive one (10,047ns). Guard the second kind; the guard on the first kind is noise.
• Redaction by censoring is faster than not redacting — but a wildcard erases customer.id and payment.last4 along with the PII, which are the two fields that made the line worth keeping. Name the paths.

---

Coming next in this thread: distributed tracing with OpenTelemetry — instrumenting across service boundaries, and the tail-sampling question a reader raised on the last post, which head-based sampling cannot answer.