En mi red de casa uso Unbound como resolver, corriendo en el ZimaBlade. Si habéis seguido las entradas anteriores ya sabéis por dónde va la cosa: primero lo puse como DNS central de la red, luego le añadí caché persistente con Redis y desde entonces no he parado de afinarlo.
Con el tiempo me hice una regla mental muy sencilla: si una consulta que ya está en caché tarda más de 1 ms, algo va mal. Nunca me había fallado.
Hasta que empezó a aparecer un 3 ms de vez en cuando. Siempre 3. Y siempre sobre dominios que estaban en caché.
🔍 Lo primero: dig no sirve para medir esto
El síntoma aparecía «cada cierto tiempo», sin patrón aparente. Ese es exactamente el tipo de problema que no se puede diagnosticar a mano, y por dos razones.
La primera es que dig redondea a milisegundos enteros. Una respuesta de 0,6 ms sale como 0 msec y una de 2,6 ms como 3 msec. Estás midiendo décimas con una regla marcada en milímetros.
La segunda es más importante: el evento resultó afectar al 0,3–0,6 % de las consultas. Con esa frecuencia necesitas unos 200 dig seguidos para esperar cazar uno. Lanzando comandos a mano puedes pasarte semanas sin verlo y concluir tranquilamente que no existe.
Así que lo primero fue tirar el dig y escribirme un medidor: consultas UDP crudas con perf_counter(), 1190 muestras en 60 segundos, y percentiles en vez de medias.
// primera medición, 1190 muestras
p50 0,269 ms
p99 0,562 ms
p99.9 3,081 ms ← aquí está
máx 82,132 ms
Y de paso el propio dato explicaba el comportamiento: la frontera entre «normal» y «pico» caía entre el p99 y el p99.9, lo que sitúa el evento por debajo del 1 % de las consultas. Por eso nunca lo pillaba a mano.
❌ Descartando lo obvio
Los picos se agrupaban de forma muy compacta entre 2,9 y 3,1 ms. Eso ya es información valiosa: el ruido aleatorio no se comporta así. Algo tardaba una cantidad concreta y repetible.
Fui descartando por medición, no por intuición:
- ¿Las lecturas a Redis? Lo uso como caché secundaria vía
cachedb, y era mi sospechoso número uno. Pero al correlacionar había consultas conGETa Redis que salían a 0 ms, y picos sin ningúnGET. Sin correlación. - ¿La carga de otros servicios? La máquina corría Open WebUI y SearXNG. Los paré del todo y volví a medir: idéntico, p99.9 de 2,95 ms. Además solo generaban 0,43 consultas por segundo.
- ¿El transporte hacia el upstream? Imposible, y lo demostraba el propio síntoma: el TTL bajaba de 288 a 287, o sea que la respuesta salía de caché. Lo que pasa aguas arriba no está en ese camino.
🐛 El culpable estaba en el código fuente
Estaba en Unbound. En util/log.c, cada línea de log se escribe así:
lock_basic_lock(&log_lock);
fprintf(logfile, ...);
fflush(logfile); // fuerza el write() en CADA línea
lock_basic_unlock(&log_lock);
write() se bloquea unos milisegundos.
La confirmación fue apagar log-queries y log-replies y volver a medir:
| Configuración | Mediana | p99.9 | Máx | Por encima de 1 ms |
|---|---|---|---|---|
| Log encendido | 0,269 ms | 3,081 ms | 82,1 ms | 0,6 % |
| Log apagado | 0,173 ms | 0,411 ms | 0,72 ms | 0 % |
⚠️ La trampa de la tanda única
Aquí casi meto la pata bien gorda. Probé una solución intermedia —dejar solo log-replies— y la primera tanda salió limpia: cero picos. Estuve a un pelo de darlo por bueno y escribir la entrada.
Repetí la medición por pura costumbre. La segunda tanda: cinco picos, uno de 13 ms.
💡 La solución: el log en RAM
La disyuntiva parecía clarísima: o latencia limpia, o log de consultas. Y el log no era prescindible, porque de él comen dos herramientas mías: un generador de listas para precacheo y un TUI de monitorización en vivo.
Pero la disyuntiva era falsa. El problema no es escribir: es escribir a un disco. Y /dev/shm es tmpfs, o sea RAM.
logfile: /dev/shm/unbound.log
Dos tandas por configuración, 1190 muestras cada una:
| Configuración | p99.9 (dos tandas) | Máx | Por encima de 1 ms |
|---|---|---|---|
| Log en disco | 3,08 / 2,95 ms | hasta 82 ms | 0,3–0,6 % |
| Log en RAM | 0,476 / 0,497 ms | 0,889 ms | 0 % |
| Log apagado | 0,411 / 0,364 ms | 0,383 ms | 0 % |
Prácticamente indistinguible de apagarlo, y con el log completo funcionando. El coste en memoria es irrelevante: 165 bytes por consulta, unos 44 MB al día, en un tmpfs de 7,8 GB.
logrotate no puede usar olddir hacia otro dispositivo, porque por debajo hace un rename().
copytruncate, que copia en vez de renombrar, más una directiva su root root porque /dev/shm es 1777.
[Service]
Type=oneshot
RemainAfterExit=yes
ExecStart=/bin/true
ExecStop=/usr/sbin/logrotate -f /etc/logrotate.d/unbound
Conviene verificar una cosa más de copytruncate: que el proceso no siga escribiendo en el offset antiguo y deje un agujero de ceros en el fichero. Unbound abre el log en modo append, así que tras el truncado vuelve al principio limpiamente. Comprobado: tamaño aparente igual al real, cero bytes nulos.
📌 Colateral: Redis, DNSSEC y las entradas caducadas
De camino apareció otra cosa que no había visto documentada en ningún sitio, y que afecta directamente a lo que monté en la entrada anterior.
Uso Redis como caché persistente vía el módulo cachedb, para que un reinicio no se lleve la caché por delante. Y sí, sobrevive: tras reiniciar tenía 11 138 claves cargadas del volcado. Pero las consultas seguían siendo lentas.
Las entradas con TTL vivo se servían perfectamente, en 0 ms. Las caducadas no, y con serve-expired activado deberían devolverse al instante como respuesta rancia mientras se refrescan por detrás. En vez de eso, resolución completa: 250–430 ms.
El log con verbosidad alta lo decía literalmente:
cachedb msg expired
Serve expired: Trying to reply with expired data
Serve expired: unchecked entry needs validation ← aborta aquí
Y el código, en cachedb.c:
/* By setting this to unchecked, bogus data is not returned
* as non-bogus. */
if(qstate->env->cfg->cachedb_check_when_serve_expired)
qstate->return_msg->rep->security = sec_status_unchecked;
mesh.c bloquea la respuesta rancia.
🚨 Y para terminar, un apagón autoinfligido
En mitad de todo esto, el DNS de casa se cayó del todo. Chrome daba DNS_PROBE_FINISHED_NXDOMAIN y todo lo que no estaba cacheado devolvía SERVFAIL.
La causa: tengo en el router unas reglas anti-bypass, para que los cacharros de la red no se salten mi resolver usando DNS cifrado.
iptables -I FORWARD -p tcp --dport 853 -j REJECT
iptables -I FORWARD -p udp --dport 853 -j REJECT
Un bloqueo sin excepciones. Que atrapa también a mi propio resolver, que necesita el puerto 853 para hablar con su upstream por DNS-over-TLS. Lo había ejecutado justo después de reiniciar el router. Y como tenía forward-first: no —sin respaldo a resolución propia, para no filtrar consultas en claro— el fallo del upstream se convirtió en caída total.
📝 Lo que aprendí
- Mide con la herramienta adecuada.
digredondea a milisegundos y toma una sola muestra. Para eventos raros hacen falta microsegundos, muchas muestras y percentiles. - Repite toda medición que decida algo. Una tanda me dijo justo lo contrario que la siguiente.
- Un resultado negativo solo vale si la prueba funcionaba. Arrastré media sesión un «paquete misterioso» que resultó no existir: era un artefacto de contar la salida de
tcpdumpcon una tubería y untimeout, que se come el búfer al morir. Capturando a fichero.pcap, y con un control que demostraba que el método sí capturaba: cero paquetes. - Comprueba quién depende de lo que vas a tocar. Apagar el log parecía inocuo. Alimentaba dos herramientas.
- Y desconfía de las disyuntivas. «O latencia o log» resultó ser mentira en cuanto pregunté por qué escribir era caro, en vez de aceptar que lo era.
Así se queda el ZimaBlade: Unbound 1.25.1 sobre Debian, cuatro hilos, caché de mensajes de 256 MB, Redis por socket unix como cachedb y DoT a Quad9 con validación DNSSEC.
Y el resumen de toda la cacería, de dónde salimos y dónde acabamos:
| Métrica | Antes | Después |
|---|---|---|
| Mediana | 0,269 ms | 0,19 ms |
| p99.9 | 3,081 ms | 0,45 ms |
| Máximo | 82,132 ms | 0,889 ms |
| Consultas por encima de 1 ms | 0,6 % | 0 % |
Nos vamos viendo por aquí, ¡gracias por leer!
