Optimización de aplicaciones en NodeJS

Los perfiles y la depuración de memoria son fundamentales para optimizar el rendimiento de las aplicaciones NodeJS. Con herramientas como --prof, --prof-process, podemos analizar el uso de memoria y CPU de nuestro código para identificar cuellos de botella y leaks de memoria.

Por ejemplo, aquí hay un fragmento de código con un cuello de botella debido a un loop ineficiente:

// app.js
const crypto = require('node:crypto');

function encrypt(input, encryptionMethod, secret, iv) {
  const encryptor = crypto.createCipheriv(encryptionMethod, secret, iv);
  const aes_encrypted = encryptor.update(input, 'utf8', 'base64') + encryptor.final('base64');
  return Buffer.from(aes_encrypted).toString('base64');
};

function decrypt(message, encryptionMethod, secret, iv) {
  const buff = Buffer.from(message, 'base64');
  message = buff.toString('utf-8');
  var decryptor = crypto.createDecipheriv(encryptionMethod, secret, iv);
  return decryptor.update(message, 'base64', 'utf8') + decryptor.final('utf8');
};

// Función costosa simulada
function doExpensiveOperation(data) {
  const secret_key = 'fd85b494-aaaa';
  const secret_iv = 'smslt';
  const encryptionMethod = 'AES-256-CBC';
  const key = crypto.createHash('sha512').update(secret_key, 'utf-8').digest('hex').substr(0, 32);
  const iv = crypto.createHash('sha512').update(secret_iv, 'utf-8').digest('hex').substr(0, 16);

  // Hacemos un loop grande para simular una operación que requiere mucho procesamiento
  let sum = 0;
  for (let i = 0; i < 1000000; i++) {
    const x = Math.random() * 1000000 + i;
    sum = sum + x;
  }

  console.log(sum);

  // Alguna transformación de datos también costosa
  data = JSON.stringify(data);
  console.log('stringify', data);
  data = encrypt(data, encryptionMethod, key, iv);
  console.log('encrypt', data);
  data = decrypt(data, encryptionMethod, key, iv);
  console.log('decrypt', data);

  return data;
}

function processData(data) {
  let results = [];
  for (let i = 0; i < data.length; i++) {
    // Llamamos la función costosa aquí
    results.push(doExpensiveOperation(data[i]));
  }
  return results;
}

console.log(processData(['esta', 'es', 'una', 'prueba']));

Para comenzar, debemos ejecutar nuestra aplicación NodeJS con la opción de generar perfiles (--prof). Esto hará que Node genere archivos de perfil que debemos procesar y finalmente tendremos una idea de como esta funcionando nuestra aplicación, por ej.

node --prof app.js

Una vez ejecutado esto, NodeJS genera un archivo con el formato isolate-0xnnnnnnnnnnnn-v8.log. Y el archivo contendrá bastante información (casi sin sentido) sobre nuestra aplicación pero para hacerlo que tenga sentido para nosotros, debemos transformarlo utilizando un comando diferente, entonces debemos nuevamente ejecutar node pero con un flag diferente --prof-process:

node --prof-process isolate-0xnnnnnnnnnnnn-v8.log > processed.txt

Y abrimos el archivo processed.txt y veremos que hay en las primeras secciones del archivo, esta lo siguiente:

[Shared libraries]:
   ticks  total  nonlib   name
     87   60.0%          /.nvm/versions/node/v18.16.0/bin/node
     12    8.3%          /usr/lib/system/libsystem_pthread.dylib
     12    8.3%          /usr/lib/system/libsystem_kernel.dylib
      9    6.2%          /usr/lib/system/libsystem_c.dylib
      7    4.8%          /usr/lib/libc++.1.dylib
      4    2.8%          /usr/lib/system/libsystem_platform.dylib

 [JavaScript]:
   ticks  total  nonlib   name
      7    4.8%   50.0%  LazyCompile: *doExpensiveOperation /test/app.js:17:30
      1    0.7%    7.1%  Function: ^requireBuiltin node:internal/bootstrap/loaders:356:24

 [C++]:
   ticks  total  nonlib   name

 [Summary]:
   ticks  total  nonlib   name
      8    5.5%   57.1%  JavaScript
      0    0.0%    0.0%  C++
      6    4.1%   42.9%  GC
    131   90.3%          Shared libraries
      6    4.1%          Unaccounted

Esta salida es útil para entender dónde se pasa el tiempo durante la ejecución de tu aplicación y para optimizar partes específicas del código. Vamos a desglosarlo para comprender que significa cada sección:

[Shared libraries]:

Este segmento muestra la cantidad de "ticks" (es como una fotografía que se toma mientras las aplicaciones que se estan ejecutando) que se pasaron en diversas bibliotecas compartidas y en la propia ejecución de Node.js.

• /.nvm/versions/node/v18.16.0/bin/node: Esta es la ejecución de Node.js. Tomó 87 ticks, lo que representa el 60.0% del tiempo total.
• Las demás entradas son bibliotecas del sistema, lo que sugiere que se pasó tiempo en operaciones del sistema, como trabajos relacionados con hilos (libsystem_pthread.dylib), llamadas al kernel (libsystem_kernel.dylib), entre otros.

[JavaScript]:

Aquí se muestran los ticks que se pasaron en el código JavaScript.

• doExpensiveOperation: Es una función en tu código (/test/app.js en la línea 17). Tomó 7 ticks, lo que sugiere que es una operación que puede estar consumiendo un tiempo significativo.
• requireBuiltin: Es una función interna de Node.js relacionada con el proceso de importación de módulos. Solo tomó 1 tick.

[C++]:

No hay entradas aquí, lo que significa que no se pasó tiempo en el código nativo de C++ durante esta ejecución.

[Summary]:

Es un resumen de la ejecución:

• JavaScript: 8 ticks en total en el código JavaScript, representando el 5.5% del tiempo total.
• C++: No hay tiempo pasado en el código nativo de C++.
• GC: 6 ticks se pasaron en la recolección de basura (Garbage Collection), representando el 4.1% del tiempo total.
• Shared libraries: 131 ticks (o 90.3% del tiempo total) se pasaron en bibliotecas compartidas.
• Unaccounted: 6 ticks (o 4.1% del tiempo total) no están contabilizados, lo que puede ser debido a varias razones, como errores de muestreo o actividades que el profiler no pudo capturar.

Interpretación:

La mayor parte del tiempo se pasó en bibliotecas compartidas y en la propia ejecución de Node.js, pero ya que estamos buscando optimizar nuestro código, podríamos considerar investigar más sobre la función doExpensiveOperation ya que parece ser la función JavaScript que más tiempo consumió.

Para arreglarlo, podemos optimizar el loop, ejecutar la operación costosa en paralelo con Promise.all() y luego del cambio podrias ejecutar el profiles para ver el resultado.

async function processData(data) {
  // Creamos un array de promises
  const promises = data.map(async item => {
    return doExpensiveOperation(item); 
  });

  // Ejecutamos todas las promesas en paralelo
  const results = await Promise.all(promises);

  return results;
}

Entonces en lugar de ejecutar doExpensiveOperation() en serie dentro de un loop, estamos creando una promesa para cada iteración y ejecutándolas concurrentemente con Promise.all().

Esto permite paralelizar la operación costosa aprovechando multiples núcleos CPU y evitar el cuello de botella del loop simple.

Y luego de hacer la corrección, ejecutamos la aplicación para tomar el perfil, y convertimos la salida a algo que podamos comprender, debería tener algo como lo siguiente:

node --prof app.js
... la salida de nuestro script

node --prof-process isolate-0x118040000-93239-v8.log > processed-optimized.txt
(node:93305) ExperimentalWarning: VM Modules is an experimental feature and might change at any time
(Use `node --trace-warnings ...` to show where the warning was created)

cat processed-optimized.txt

[Shared libraries]:
   ticks  total  nonlib   name
     89   62.2%          /.nvm/versions/node/v18.16.0/bin/node
     15   10.5%          /usr/lib/system/libsystem_kernel.dylib
     12    8.4%          /usr/lib/system/libsystem_pthread.dylib
      9    6.3%          /usr/lib/system/libsystem_c.dylib
      6    4.2%          /usr/lib/libc++.1.dylib
      3    2.1%          /usr/lib/system/libsystem_platform.dylib

 [JavaScript]:
   ticks  total  nonlib   name
      5    3.5%   55.6%  LazyCompile: *doExpensiveOperation /test/test.js:17:30

 [C++]:
   ticks  total  nonlib   name

 [Summary]:
   ticks  total  nonlib   name
      5    3.5%   55.6%  JavaScript
      0    0.0%    0.0%  C++
      3    2.1%   33.3%  GC
    134   93.7%          Shared libraries
      4    2.8%          Unaccounted

Y después del cambio que hemos realizado, hemos logrado un efecto positivo en el rendimiento del código, ya que la función doExpensiveOperation ahora consume menos ticks. Sin embargo, el tiempo total en bibliotecas compartidas ha aumentado ligeramente, pero es normal ya que no podemos tener una aplicación consumiendo 0 tickts y hemos delegado la ejecución a los promises.

Ahora, veamos otro ejemplo, esta vez de un memory leak:

// Simula una llamada a un API o servicio web
function getDataFromNetwork() {
  // Esperamos para simular latencia
  const waitTime = Math.random() * 3000;
  return new Promise(resolve => {
    setTimeout(() => {
      // Devolvemos datos haciendo mocking
      resolve([
        {id: 1, title: 'Data 1'},
        {id: 2, title: 'Data 2'},  
        {id: 3, title: 'Data 3'}
      ]);
    }, waitTime);
  });
}

async function processNetworkData() {
  // Obtenemos los datos
  const data = await getDataFromNetwork();

  // Procesamos los datos
  const processor = new Processor();
  processor.process(data);

  return data;
}

processNetworkData();

Aquí hay un leak porque estamos creando una nueva instancia de Processor cada vez, pero nunca la eliminamos. Si llamamos esta función muchas veces, la memoria seguirá creciendo.

Para encontrar este tipo de leaks, debemos tomar múltiples perfiles durante un periodo y comparar el consumo total de memoria entre ellos. Si la memoria crece constantemente, tenemos un leak.

La versión optimizada del código anterior debería verse de la siguiente manera:

// Simula una llamada a un API o servicio web
function getDataFromNetwork() {
  // Esperamos para simular latencia
  const waitTime = Math.random() * 3000;
  return new Promise(resolve => {
    setTimeout(() => {
      // Devolvemos datos haciendo mocking
      resolve([
        {id: 1, title: 'Data 1'},
        {id: 2, title: 'Data 2'},  
        {id: 3, title: 'Data 3'}
      ]);
    }, waitTime);
  });
}

// Creamos una instancia única de Processor fuera de la función
const processor = new Processor();

async function processNetworkData() {
  // Obtenemos los datos
  const data = await getDataFromNetwork();

  // Procesamos los datos utilizando la instancia reutilizada
  processor.process(data);

  return data;
}

processNetworkData();

Con esta estructura de código, estaríamos reutilizando una única instancia de Processor en lugar de crear una nueva cada vez que se llama a processNetworkData(). Esto debería ayudar a prevenir posibles fugas de memoria y optimizar el rendimiento, especialmente si se esta llamando a processNetworkData() muchas veces.

Otra opción es utilizar el módulo memwatch-next para monitorear la asignación de memoria en tiempo real. Podemos instalarlo usando el siguiente comando:

yarn add memwatch-next -D

Y usarlo en nuestro código NodeJS:

const memwatch = require('memwatch-next');

const hd = new memwatch.HeapDiff();

// código que queremos monitorear 

const diff = hd.end();

console.log(diff);

Esto nos dará detalles sobre cuánta memoria se asignó entre el inicio y fin de HeapDiff.

El heap es la región de memoria donde se alojan los objetos en JavaScript. Cuando se crean instancias y variables, se asigna memoria para ellos en el heap.

En aplicaciones de NodeJS, el consumo de memoria debería mantenerse dentro de un rango razonable, sin crecer indefinidamente ni tener picos excesivos que puedan causar problemas.

Algunas pautas generales para evitar memory leaks y picos de memoria:

• Liberar referencias a objetos grandes cuando ya no se necesiten (por ejemplo llamando delete o asignando a null)

• No acumular datos innecesariamente en arrays/objects globales

• Limitar el tamaño de caches basados en tiempo o cantidad

• Evitar closures que capturen referencias a objetos que no se liberan

• Manejar adecuadamente streams para no bufferizar datos en memoria

• Limitar la concurrencia si hace operaciones muy intensivas de memoria

• Monitorear el consumo con herramientas como Chrome DevTools o memwatch

• Hacer pruebas de carga para detectar fugas antes de deploy a producción

Si se siguen buenas prácticas como estas y se monitorea activamente, es totalmente posible y deseable tener una aplicación Node con un consumo de memoria estable y predecible.

Identificar y solucionar problemas de rendimiento y memoria temprano en el desarrollo puede ahorrarnos muchos dolores de cabeza a futuro. Las herramientas de profiling de Chrome, junto con módulos como memwatch, son invaluables para lograrlo, toma tiempo aprender a utilizar estas herramientas y mejor aún entenderlas, pero una vez dominadas, deberías ser capaz de comprender y arreglar tus aplicaciones en cuestión de horas.

Happy coding! :D

Photo by Mike Hindle on Unsplash