Historia de un memory leak en Node JS: Un viaje de debugging

Diseñar y crear sistemas web puede ser muy difícil. Llevo años desarrollando software usando arquitecturas de microservicios y Node.js y de vez en cuando te encuentras con situaciones que te obligan a aprender mucho. Esta es la historia de uno de esos momentos.

La configuración: event tracking a escala

Una de las cosas que construimos en TES fue una plataforma ETL, cuya principal responsabilidad era recopilar, almacenar y transformar datos de múltiples fuentes, así como poner estos datos a disposición de aplicaciones y científicos de datos a través de diferentes APIs.

Una de estas fuentes eran eventos significativos que ocurrían en el navegador:

• Solicitudes de empleo
• Vistas de página
• Descargas de documentos
• Interacciones de usuario

Creamos un microservicio para este propósito llamado event tracking. Su principal responsabilidad era servir como punto de entrada para eventos del navegador, enriquecer el payload con información de sesión de las cookies y almacenar inmediatamente los datos en RabbitMQ para su posterior consumo. Aquí es donde se desarrolló nuestra historia.

Cuando las alertas empiezan a gritar

Este servicio había estado funcionando bien durante el último año aproximadamente y apenas hicimos cambios una vez que lo construimos (eso era una buena señal). Como usábamos Datadog, decidimos crear alertas estándar en todos nuestros contenedores docker para reportar el consumo de CPU y memoria de cada servicio.

Poco después recibimos una alerta «aleatoria» advirtiendo que nuestro servicio de event tracking estaba utilizando sus niveles de memoria por encima de su asignación inicial de 1 GB. Al principio simplemente piensas «qué raro», y como después de un rato sus niveles de memoria volvieron a la normalidad, estábamos convencidos de que era solo un evento aleatorio y extraño que nunca volvería a suceder.

Hasta que al día siguiente volvió la misma alerta. Y pensamos… vale.

Evaluando el impacto

Es difícil pensar con claridad cuando te das cuenta de que estás frente a una bomba de relojería a punto de estallar, pero lo primero que hicimos fue evaluar cómo de grave era esto, para priorizar el problema.

Por qué era crítico

Si un microservicio se reinicia debido a un problema técnico pero está respaldado por RabbitMQ o está a cargo de una transacción que se revierte desde una base de datos, puede que no sea el fin del mundo. Sin embargo, debido a la naturaleza de este servicio, y aunque teníamos x3 réplicas del mismo contenedor docker en diferentes servidores, esto significaba que podríamos haber perdido datos valiosos si el servicio dejaba de estar disponible.

Teníamos un problema P1 real. Curioso, ya que esto probablemente había estado ocurriendo desde el principio, pero ahora estaba en nuestro radar.

Intentando apagar el fuego

Si tu casa estuviera en llamas no intentarías inmediatamente averiguar por qué pasó eso: simplemente le tirarías cubos de agua, sofocarías el fuego y entonces comenzarías tu investigación.

En este caso, como teníamos una fuga de memoria obvia, intentamos aumentar el umbral de memoria en el contenedor docker hasta 3GB, esperando que eso aliviara la fuga de memoria aún desconocida y ofreciera más información al respecto.

Alivio temporal, información valiosa

Por supuesto, esto no lo solucionó, pero fue útil por dos razones:

1. Nuestro servicio se reiniciaría más tarde y con menos frecuencia
2. Podíamos observar claramente y correlacionar el inicio de la generación de fuga de memoria con el inicio de la hora pico en TES, donde se recibía una gran cantidad de eventos

Decidimos mantener los límites de memoria en 3GB. Otra solución temporal es hacer que tu servicio se reinicie antes de que sea demasiado tarde. Pero obviamente necesitábamos investigar más a fondo. Y así lo hicimos.

Siguiendo el método científico

Con nuestra solución temporal en su lugar y algunos datos valiosos recopilados, era hora de dejar de apagar incendios y comenzar a investigar adecuadamente. Necesitábamos un enfoque estructurado para abordar este problema, no solo intentos aleatorios de arreglar las cosas. Fue entonces cuando decidimos aplicar el método científico a nuestro proceso de debugging: sí, el mismo método que aprendiste en la escuela funciona también para perseguir fugas de memoria en sistemas de producción.

El método científico es un método empírico de adquisición de conocimiento que involucra observación cuidadosa, formulación de hipótesis, a través de la inducción, basada en tales observaciones; pruebas experimentales y medición de deducciones extraídas de las hipótesis; y refinamiento (o eliminación) de las hipótesis basado en los hallazgos experimentales.

Formulación de hipótesis

Como dice la definición, necesitábamos formular una hipótesis basada primero en una observación cuidadosa. Esencialmente, necesitábamos un hilo del que tirar. Gracias a nuestra monitorización y los diferentes resultados después de alterar el umbral de memoria en el contenedor docker, notamos que la fuga de memoria siempre comenzaba a manifestarse durante las horas pico.

Nuestra primera hipótesis fue: «Esta fuga de memoria se manifiesta durante la hora pico, por lo que nuestro servicio no gestiona la memoria correctamente cuando recibe una gran cantidad de eventos».

No sabíamos mucho más que eso en ese momento. Solo necesitábamos probar esta teoría, entender por qué sucedía y arreglarlo. Fácil, ¿verdad?

Pruebas experimentales

Normalmente alcanzábamos la hora pico alrededor de las 12:00 hora del Reino Unido durante los días entre semana. Obviamente no podíamos probar en el entorno en vivo, y mucho menos esperar 24 horas hasta poder intentarlo de nuevo. Por eso lo primero en lo que nos enfocamos fue en intentar reproducir las condiciones ambientales localmente. Si lo lográbamos, esto facilitaría masivamente nuestra investigación.

Afortunadamente fue relativamente fácil reproducir el problema bombardeando nuestro servicio localmente con miles de eventos. La memoria en nuestro proceso de node aumentaría indefinidamente. Había esperanza.

Medición de deducciones

Si no tienes una medida no puedes decir si has solucionado el problema o no. En nuestro caso, el consumo de memoria era fácil de verificar. Por eso usamos herramientas para tomar instantáneas de los niveles de memoria. Esto nos permitió descubrir que nuestra fuga de memoria estaba relacionada con las publicaciones de RabbitMQ.

Encontrando al culpable

Usamos la técnica de divide y vencerás para encontrar exactamente dónde en el código estábamos teniendo problemas. Esta es una versión simplificada del lugar donde detectamos el problema:

const handler = (message, content, ackOrNack) => {
   broker.publish('eventsAll', event, (err, publication) => {
      if (err) {
        // error handling here
        return;
      }
      publication
      .on('success', () => { // some logging + monitoring })
      .on('error', () => { // some logging + monitoring });
   }

   ackOrNack();
};

Como puedes ver, estábamos usando fire and forget en este handler. Estábamos publicando en RabbitMQ (usando esta increíble librería), pero no estábamos esperando a que terminara (ackOrNack se llama inmediatamente después).

El cuello de botella revelado

Lo que observamos fue: nuestros callbacks de publicación estaban tardando mucho más tiempo en resolverse una vez que comenzábamos a disparar una gran cantidad de eventos. Para probar este comportamiento colocamos algo de timing en el monitoreo y obtuvimos este resultado:

Como puedes ver, el tiempo para que el callback de publicación se resolviera estaba aumentando en hora pico (cuando estaba ocurriendo la fuga de memoria) lo que esencialmente sugería que había un cuello de botella: estábamos produciendo callbacks mucho más rápido de lo que los resolvíamos. Pero aún no sabíamos exactamente por qué, así que nos enfocamos en arreglar el tiempo de publicación, pensando que eso llevaría a solucionar la fuga de memoria.

Elige tus medidas sabiamente: No empeores las cosas

Pensamos que si arreglábamos el tiempo de publicación eso significaría que el servicio podría mantener un ritmo saludable al procesar eventos, y por lo tanto la fuga de memoria desaparecería:

const handler = (message, content, ackOrNack) => {
   broker.publish('eventsAll', event, (err, publication) => {
      if (err) {
        // error handling here
        return;
      }
      publication
      .on('success', () => {
          // some logging + monitoring
          ackOrNack();
      })
      .on('error', () => {
         // some logging + monitoring
         ackOrNack();
      });
   }
};

Estábamos esencialmente eliminando el fire and forget. Como puedes ver, el ackOrNack solo se llamaba después de que se completaba la publicación. Esto, de hecho, mejoró el tiempo de publicación y el consumo de memoria en nuestro entorno local, así que felizmente lo pusimos en producción, pensando que el arreglo estaba hecho.

Cuando la cura es peor que la enfermedad

Pero poco después de ponerlo en producción comenzamos a recibir 503 de nuestros servicios. Esto es malo. De nuevo, siguiendo la metáfora del fuego, inmediatamente revertimos nuestros cambios. Necesitábamos pensar un poco más profundo.

Esencialmente lo que estaba pasando era: nuestros cambios estaban siendo contraproducentes. Eliminamos el cuello de botella de RabbitMQ, pero lo colocamos en otro lugar: en los servidores HTTP. Todas las conexiones HTTP tardaban más en resolverse, porque ahora cada solicitud de evento tardaría más en procesarse ya que estaban esperando a que los callbacks de publicación terminaran. Esto saturó el servidor Express con conexiones pendientes crecientes, y no permitía ningún otro evento entrante.

El arreglo que intentamos funcionaría bien si pudiéramos controlar la entrada (como una suscripción de RabbitMQ), pero no cuando tienes una cantidad incontrolada de eventos entrando. Además, con nuestros servicios devolviendo 503, el navegador no reintentaría enviar esos eventos, así que estábamos perdiendo datos bajo esa situación.

Refinamiento Basado en los Hallazgos Experimentales

La experimentación y los errores nos dieron mucha información. Sabíamos que el cuello de botella estaba ocurriendo porque las publicaciones estaban tardando demasiado tiempo en resolver sus callbacks bajo alta presión. También sabíamos que no podíamos hacer que los clientes HTTP esperaran por ellos.

La Solución: Channel Pools

Así que la única solución era hacer las publicaciones más rápidas. En la librería rascal que estábamos usando había una colección de commits que hacían configurables los pools de canales de publicación. El valor por defecto, sin embargo, estaba establecido en 1 (recomendado a menos que sepas lo que estás haciendo). Todo lo que teníamos que hacer era aumentar el tamaño del pool en nuestro servicio:

{
  "rascal": {
    "defaults": {
      "vhosts": {
        "publicationChannelPools": {
          "regularPoolSize": 15,
          "confirmPoolSize": 15
        }
      }
    }
  }
}

Esta pequeña modificación en la configuración es todo lo que tuvimos que hacer. Mira el gráfico del tiempo de publicación antes y después de que hiciéramos este cambio:

Lo mismo sucedió con el consumo de memoria, que se mantuvo en niveles muy bajos y razonables después de que nuestro arreglo fue enviado al entorno en vivo.

Lecciones aprendidas: conclusiones clave

Espero que este artículo pueda mostrar algunos de nuestros aprendizajes en el proceso de perseguir una fuga de memoria. Estas son nuestras lecciones de esta historia:

• Monitoriza tus signos vitales (memoria y CPU al menos) por defecto en todos tus servicios: este problema estuvo allí todo el tiempo, simplemente no lo sabíamos
• Reproduce los problemas localmente si quieres enfocar toda tu energía en el arreglo, en lugar de perseguir fantasmas
• Usa herramientas de debugging para el consumo de memoria: es absolutamente clave
• Entiende el event loop y cómo funcionan los callbacks y cómo podrían afectar los niveles de memoria de tu servicio
• Sigue el método científico como marco para hacer tu investigación, en lugar de probar cosas aleatoriamente
• Prueba tus arreglos exhaustivamente: a veces la cura puede ser peor que la enfermedad

Las fugas de memoria en Node.js pueden ser sutiles y desafiantes de depurar, especialmente bajo cargas de producción. Pero con el monitoreo adecuado, la metodología y la paciencia, incluso los problemas más complicados se pueden resolver. La clave es observar, formular hipótesis, probar y refinar. Repite el proceso hasta encontrar la causa raíz.