Pino y Serilog, medidos: el sink asíncrono es rápido porque descarta líneas

El checkout de Aurora Coffee Co. escribe una línea de log estructurada por cada orden. Quería saber cuánto cuesta eso, así que registré el mismo evento 200.000 veces por cada configuración de destino que se me ocurrió, en Node 24 y en .NET 10. Dos líneas de la corrida de Serilog:

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

Envolver el destino en WriteTo.Async duplicó el rendimiento y dividió el p99 entre siete. Ese es el resultado que todo el mundo cita, y la razón por la que ese envoltorio aparece en casi todas las configuraciones de Serilog que he leído.

Después conté las líneas que llegaron al archivo:

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 líneas de log no existían. Sin excepción, sin advertencia, sin ningún contador en la aplicación. El sink asíncrono era el doble de rápido porque estaba haciendo algo más de un tercio del trabajo.

Este artículo es lo que encontró el resto de ese banco de pruebas: cuánto cuesta la estructura (menos de lo que crees), cuánto cuesta el destino (más de lo que crees), y cuál de los dos valores por defecto que tienes delante pierde datos en silencio.

El montaje, para que los números signifiquen algo

Cada número de aquí sale de un arnés por runtime que registra el mismo evento —una orden con cinco campos— 200.000 veces, después de 2.000 iteraciones de calentamiento. Cada llamada se cronometra por separado con process.hrtime.bigint() en Node y Stopwatch.GetTimestamp() en .NET, así que la cola es real y no una resta del total.

Dos detalles importan más de lo que parecen.

El bucle cede el control. Mi primera corrida en Node daba el destino con búfer más lento que el síncrono, lo cual es imposible. La causa era el banco de pruebas, no el destino: un bucle síncrono cerrado nunca vuelve al event loop, así que un destino con búfer no puede vaciarse y simplemente acumula — 40 MB de acumulación. Ceder el control cada 1.000 iteraciones lo arregló. Si tu medición de logging muestra que el búfer empeora las cosas, es por esto.

Los conteos de líneas se verifican. Cada arnés termina contando las líneas de cada archivo y comparándolas con lo que registró. Esa comprobación es la única razón por la que existe este artículo; sin ella, el resultado asíncrono de Serilog se lee como una victoria limpia.

// bench.ts — la forma de cada medición
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;
    // Sin esto el event loop nunca corre y un destino con búfer no puede vaciarse.
    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)}`,
  );
}

El hardware es un portátil, no un servidor, así que fíjate en las proporciones y no en las cifras absolutas.

---

Cuánto cuesta de verdad la estructura

El miedo es que serializar JSON sea caro comparado con escribir una cadena. Esta es la corrida de Node, las seis configuraciones, tal cual:

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

El logging estructurado cuesta un 9%. 5.181 ns contra 4.733 ns de construir a mano la cadena equivalente y escribirla al mismo descriptor de archivo. Esa es toda la penalización de serializar, y a cambio obtienes una línea que una máquina puede filtrar en lugar de una que una expresión regular tiene que adivinar.

El lado de .NET es menos halagador y más interesante:

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

El sink de texto de Serilog es más lento que el de JSON: 7.888 ns contra 6.081 ns. Convertir una plantilla de mensaje en una frase legible cuesta más que emitir el documento estructurado, porque convertir significa formatear cada propiedad dentro de una cadena, mientras que el formateador JSON escribe los valores donde ya están. El formato legible es el caro. Si conservas un sink de texto porque el JSON "tiene que pesar más", es al revés.

Lo que no sale gratis son los bytes:

	bytes por línea	relativo
texto, Node	112	1,0×
JSON, Node (pino)	203	1,8×
texto, .NET	117	1,0×
plantilla renderizada, .NET	176	1,5×
JSON compacto, .NET (Serilog)	262	2,2×

Esa es la factura de verdad, y no es de CPU. A mil líneas por segundo, los 91 bytes extra por línea de pino son 7,9 GB al día de almacenamiento e ingesta que antes no tenías: 86,4 millones de líneas por 91 bytes. Todos los productos de logs cobran exactamente por ese número.

---

El destino, que es donde está el dinero

Un logger hace dos cosas: convertir un evento en bytes y llevar esos bytes a algún sitio. Lo primero es lo que miden los bancos de pruebas. Lo segundo es lo que te despierta de madrugada.

Síncrono

La escritura ocurre en el hilo que llama. Tu petición espera al disco. Con un SSD local y la caché del sistema delante, eso suele estar bien. Y a veces no:

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

La media son 6 µs. El máximo son 47 milisegundos, para una sola llamada de log. Es una petición, en algún punto de esas 200.000, que pasó una veinteava parte de segundo dentro de Log.Information. Nada del código es lento; el sistema operativo decidió vaciar a disco y el llamador lo pagó. Los sinks síncronos ponen la cola del almacenamiento sobre la cola de tus peticiones, y una media no te lo va a enseñar nunca.

Con búfer, estilo Node

El destino con búfer de pino entrega los bytes a un búfer interno y regresa. Lo apunté a un destino que tarda 2 ms por vaciado —un recolector de logs saturado, un volumen de red, un disco bajo presión— y registré 20.000 líneas:

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

El llamador nunca esperó: un p50 de 1,9 µs frente a un destino que tarda dos milisegundos por vaciado. Se completaron veintiún vaciados en el tiempo que costó registrar veinte mil líneas, y la memoria residente creció 16,2 MB. El atasco no desapareció: está en el heap, esperando a un destino que no da abasto.

Ese es el intercambio, dicho sin rodeos: un destino con búfer no abarata la escritura, la convierte en problema de otro para más tarde, y ese "más tarde" se guarda en la memoria de tu proceso. Si el destino sigue lento, no recibes una alerta de latencia. Recibes un proceso eliminado por falta de memoria, que es una forma bastante peor de enterarte.

Y cuando el proceso se muere

La razón por la que registras logs suele ser que algo salió mal. Así que registré 50.000 líneas en un destino con búfer de pino y maté el proceso como se mueren los procesos de verdad: sin vaciado y sin manejador de cierre.

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

Una línea. El búfer está en la memoria de un proceso muerto, y el archivo tiene lo que se hubiera vaciado antes de morir. Un process.on('exit') que llame a flushSync() cierra casi todo este agujero, y un SIGKILL o una caída dura lo vuelven a abrir entero.

Asíncrono, estilo .NET

WriteTo.Async pone una cola acotada y un hilo de fondo entre tu código y el sink. La cola por defecto son 10.000 eventos, y el comportamiento por defecto cuando se llena es descartar. Estas son las tres configuraciones de Serilog de la misma corrida:

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

Y los conteos de líneas de esos tres archivos:

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

Lee los dos bloques juntos y el panorama se invierte:

configuración	rendimiento	líneas conservadas
síncrono	164 k/s	202.000
asíncrono, por defecto	331 k/s	80.256
asíncrono, blockWhenFull: true	122 k/s	202.000

El sink asíncrono que conserva tus datos es más lento que no poner ningún sink asíncrono. 122 k/s contra 164 k/s: la cola, el traspaso y el cambio de contexto cuestan más de lo que ahorran en cuanto dejas de permitirle descartar lo que sobra. La configuración que todo el mundo copia es la fila de en medio, y la fila de en medio perdió el 60% de los eventos.

Conviene advertir algo sobre ese número: este banco de pruebas machaca el logger en un bucle cerrado, mucho más fuerte de lo que lo hará un servicio real, así que en producción la cola se vacía entre peticiones y casi nunca descarta nada. La conclusión no es "te falta el 60% de los logs". La conclusión es que el descarte es silencioso y nadie lo mide, así que la única vez que importa —un incidente, una tormenta de reintentos, el pico que más querías ver registrado— no vas a saber que ocurrió. Si usas WriteTo.Async, pon blockWhenFull: true y acepta la latencia, o conecta su callback monitor para que la profundidad de la cola sea una métrica que puedas ver.

---

Niveles: la llamada que creías gratis

Una llamada de log desactivada igual evalúa sus argumentos. El objeto se construye, la cadena se interpola, la pila se captura, y solo entonces el logger decide tirarlo todo.

Cuánto cuesta eso depende por completo del payload, y los dos casos están separados por cuatro órdenes de magnitud:

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)

Con un objeto plano, una llamada de debug descartada cuesta 83 ns en pino y 27 ns en Serilog: gratis, para cualquier propósito. Protegerla con isLevelEnabled no cambia nada; pino sale a 97 ns protegida frente a 83 ns sin proteger, que es ruido en la dirección equivocada.

Con un payload que cuesta construir —aquí una traza de pila capturada— esa misma llamada descartada cuesta 10.047 ns en pino y 12.981 ns en Serilog. Eso es el doble que una línea de log activa que sí se escribe. Protegida, baja a 97 ns y 18 ns.

Así que el consejo de "protege siempre tus llamadas de debug" y el de "no te molestes, el logger es rápido" están los dos equivocados, y la regla es mecánica:

Protege una llamada de nivel desactivado cuando, y solo cuando, construir sus argumentos haga trabajo real. Un objeto serializado, un JSON.stringify, una traza de pila, una consulta a base de datos para obtener un nombre legible, un string.Join sobre una colección. Si el payload son campos que ya tienes a mano, la protección es estorbo.

Los números de .NET traen una nota extra: las plantillas de mensaje de Serilog difieren el formateo automáticamente, y por eso su caso de payload plano es tres veces más barato que el de pino. Lo que no se difiere es la expresión del argumento. Log.Debug("{Trace}", new StackTrace().ToString()) construye la traza de pila quiera alguien verla o no.

---

Enmascarar datos, que es a donde fue a parar la PII

Todo el valor del logging estructurado es que registras el objeto en lugar de una frase sobre el objeto. Lo que significa que tarde o temprano registras al cliente:

{"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"}}

La opción redact de pino toma rutas y las censura o las elimina. Medí cuatro configuraciones contra el mismo payload anidado:

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

Censurar es más rápido que no enmascarar nada: 7.284 ns contra 8.406 ns, porque [redacted] es más corto que una dirección y queda menos JSON que escribir. Enmascarar no es un costo que estés pesando contra la seguridad. Es gratis, y en el caso habitual sale a favor.

remove: true es la opción lenta, 10.032 ns, porque borrar claves cuesta más que sobrescribir valores. Prefiere censurar, salvo que una clave ausente rompa a quien lee después.

Y luego la trampa, que es la razón de imprimir la salida de cada configuración en vez de fiarse:

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]"}

La versión con comodín —customer.* y payment.*, la configuración que escribes con prisa queriendo ir sobre seguro— también censuró customer.id y payment.last4. Esos no son datos personales: son los dos campos que hacían útil la línea. Alguien de soporte puede encontrar una orden con cus-5521. No puede encontrar nada con [redacted].

Nombra las rutas. En .NET el equivalente es una política Destructure.ByTransforming<T>() en la configuración del logger, y tiene la misma propiedad: sé específico o borrarás tus propias claves de correlación.

---

Los campos que conviene acordar

Nada de esto sirve si dos servicios llaman distinto a lo mismo. Consultar entre servicios es el objetivo entero, y lo que lo rompe es el vocabulario, no el volumen. La lista corta que se gana su sitio:

• service y version — qué desplegable y qué compilación. El segundo responde "¿esto empezó con la release?" sin tener que adivinar.
• trace_id y span_id — la unión con tus trazas. Los dos loggers los añaden solos bajo OpenTelemetry; el artículo anterior de esta línea cubre el cableado y el hook del cargador que, si falta, lo impide en silencio.
• Un identificador de dominio por evento — order_id, no id. Un campo llamado id en cuatro servicios son cuatro cosas distintas en un mismo índice.
• error.type y error.stack como campos separados, nunca una cadena ya formateada. El tipo es por lo que agrupas; la pila es lo que lees después.
• Un level normalizado — los dos loggers no se ponen de acuerdo por partida doble, que es la siguiente sección.

El campo de nivel es peor que un desacuerdo de nombres

Registrando un info y un warning con cada librería, y leyendo lo que quedó. El base de pino está puesto al desplegable en vez de dejarlo por defecto, que es la primera recomendación de abajo y además mantiene el nombre de la máquina fuera de cada línea:

{"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 escribe un número. Serilog escribe un nombre. Hasta ahí es una tabla de equivalencias en el recolector.

Lo que pilla a la gente es la primera línea de Serilog: no hay @l por ningún lado. El JSON compacto omite el nivel cuando es Information, porque es el valor implícito. Así que un panel que filtre level = "Information" no devuelve nada de tus servicios .NET —no pocos resultados, ninguno— mientras que level >= 40 no devuelve nada de los de Node. Normaliza los dos en el recolector, y trata el campo ausente como Information en vez de como algo que no se pudo interpretar.

Acuerda esos seis y podrás hacerle una pregunta a toda la flota. Sáltatelo y tendrás una forma muy rápida de producir JSON que nadie puede consultar.

---

Cuándo usar qué

Registra estructurado desde la primera línea de un servicio nuevo. Cuesta un 9% en Node y en .NET es más barato que el texto renderizado. No hay un umbral a partir del cual empiece a valer la pena; solo está la migración que te tocará hacer después.

Deja el destino en síncrono hasta que midas que duele. Es la única configuración que no puede perder datos en silencio, y sobre un disco local su media está en microsegundos de un dígito. Renuncia a eso a propósito, no por copiar un fragmento de configuración.

Si te vas a asíncrono, haz visible la pérdida. blockWhenFull: true en Serilog, un vaciado al salir en Node, y la profundidad de la cola como métrica. Un sink asíncrono sin contador de eventos descartados es un sistema que te miente justo bajo la carga que te importa.

No registres en debug en producción confiando en que el nivel te salve: solo te salva de la escritura, no de construir el payload. Protege las llamadas caras.

Regla práctica: el costo del logging estructurado son bytes, no CPU. Presupuesta almacenamiento, mide el destino, y que un búfer no sea nunca la única copia de algo que ibas a necesitar.

---

Puntos clave

• La estructura cuesta alrededor de un 9% de CPU y 1,8× los bytes. En .NET, el sink JSON de Serilog es más rápido que el de texto renderizado —6.081 ns contra 7.888 ns— así que el formato legible para humanos es el caro.
• WriteTo.Async duplicó el rendimiento descartando 121.744 de 202.000 líneas. Su valor por defecto es descartar cuando la cola se llena, en silencio. Con blockWhenFull: true lo conserva todo y va más lento que no poner el envoltorio.
• Un destino con búfer traslada el costo a tu heap. Contra un destino de 2 ms, el llamador se quedó en 1,9 µs mientras la memoria residente crecía 16,2 MB — y un cierre abrupto dejó 1 de 50.000 líneas en disco.
• Una llamada de debug descartada es gratis con un payload plano (83 ns) y cuesta más que un log real con uno caro (10.047 ns). Protege las del segundo tipo; la protección en las del primero es ruido.
• Censurar al enmascarar es más rápido que no enmascarar — pero un comodín borra customer.id y payment.last4 junto con los datos personales, que son los dos campos que hacían valiosa la línea. Nombra las rutas.

---

Lo que sigue en esta línea: trazado distribuido con OpenTelemetry — instrumentar a través de los límites de proceso, y la pregunta sobre muestreo de cola que planteó un lector en el artículo anterior, que el muestreo de cabecera no puede responder.