DEV Community: Andrés Estévez

Cómo medir el rendimiento en NodeJS

Andrés Estévez — Sat, 11 Apr 2020 15:57:02 +0000

En un post anterior se explicaba cómo se puede mejorar el rendimiento de una aplicación sin necesidad de reimplementarla en otro lenguaje más rápido. La propuesta consistía en refactorizarla usando otros tipos de datos y algoritmos que proporcionasen un mayor rendimiento.

Ahora bien, ¿cómo detectamos y decidimos que debemos reimplementar una parte de nuestro código? Por una sospecha. Intuimos que alguna parte de nuestro código es la que está limitando el tiempo de ejecución total de la aplicación, así que es ahí donde debemos actuar. Sin embargo, esta intuición puede ser errónea, y la mejora de rendimiento puede no compensar el tiempo que dediquemos a reimplemetar esta parte del código. Por tanto, antes de reimplementar nada, verifiquemos que nuestra intuición es acertada. Es decir, midamos cuánto tiempo tarda en ejecutarse esa parte del código y comparémoslo con el tiempo total. Si supone un porcentaje significativo entonces estaremos ante un fragmento de código donde merece la pena dedicar esfuerzo a mejorar el rendimiento.

Midiendo el tiempo en NodeJS

En NodeJS existen varios mecanismos para medir el tiempo de ejecución. Algunos de ellos se caracterizar por obligar al programador a indicar cuáles son las zonas de código a medir, como console.time o la Performance Timing API. Otra aproximación es el profiling, o análisis de rendimiento en tiempo de ejecución. Veremos que una aplicación NodeJS se puede ejecutar en modo profiling y, al finalizar, se genera automáticamente un informe con los tiempos de ejecución de cada función. La interpretación de este informe puede ser un tanto tediosa y difícil, por lo que se han desarrollado herramientas visuales que ayuda a su interpretación, como clinicjs.

A continuación explico cada uno de los métodos usando el siguiente código como ejemplo. Se trata de una funcíon slowFunc que llama a otras dos, add y div. Al ejecutarlo nos daremos cuenta de que hay un cierto retardo, cuando el código debería ser inmediato, ya que realiza simplemente una suma y una división. Veamos cómo depurar el rendimiento.



   const add = (a, b) => {
      return a+b
   }

   const div = (a, b) => {
      const startAt = new Date();
      if (b === 0) {
         throw Error;
      }

      // code to consume CPU cycles
      while (Date.now() - startAt < 1000) {}

      return a/b;

   }

   const slowFunc = (a, b) => {
      const sum = add(a, b);

      const result = div(sum, 10);
   }

   slowFunc(10, 20);

console.time

Con esta herramienta podemos medir el tiempo de ejecución entre dos puntos de nuestro código. El primero será aquel en el que escribimos console.time(<etiqueta>), y el segundo console.timeEnd(<etiqueta>). Los instantes de paso se grabarán de manera transparente y, en la terminal veremos cómo se escribe el tiempo transcurrido entre ambos. Para nuestro código de ejemplo, tendríamos:



   const add = (a, b) => {
      return a+b
   }

   const div = (a, b) => {
      const startAt = new Date();
      if (b === 0) {
         throw Error;
      }

      // code to consume CPU cycles
      while (Date.now() - startAt < 1000) {}

      return a/b;

   }

   const slowFunc = (a, b) => {
      console.time('slowFunc');
      const sum = add(a, b);

      console.time('div');
      const result = div(sum, 10);
      console.timeEnd('div');

      console.timeEnd('slowFunc');
   }

   slowFunc(10, 20);

En la terminal aparecerá:



div: 1000.220ms
slowFunc: 1002.300ms

Observamos lo siguiente:

es posible poner un bloque time... timeEnd dentro de otro
la etiqueta que pusimos en el código, div y slowFunc se usan para identificar en la terminal cada uno de los tiempos medidos.
se observa que hay una fragmento del código que ocupa casi todo el tiempo total. En este caso, el código del div representa casi el total de slowFunc. Por tanto este será el código a refactorizar para mejorar su eficiencia.
se trata de un mecanismo invasivo, ya que es necesario introducir líneas de código en el propio código que queremos probar

Performance API

NodeJS proporciona una interfaz de menor nivel para medir el rendimiento, que permite realizar cálculos más sofisticados y dar más control al desarrollador. Se trata de una API bastante amplia, por lo que en este post nos ceñiremos a lo siguiente:

medir el tiempo entre dos puntos del código
medir el tiempo de ejecución de una función

Tiempo entre dos puntos del código

Para esta tarea se realizará un proceso similar al explicado en console.time: indicaremos el principio y final del bloque de código que queremos medir:



   performance.mark(<etiqueta de inicio>);
   <código a medir>
   performance.mark(<etiqueta de fin>)

La primera diferencia con el mecanismo anterior viene ahora: el valor medido no aparece automáticamente en pantalla. Para obtenerlo es necesario que lo pidamos explícitamente:



   performance.mark(<etiqueta de inicio>);
   <código a medir>
   performance.mark(<etiqueta de fin>);
   performance.measure(<etiqueta de la medición>, <etiqueta de inicio>, <etiqueta de fin>);

¿Y dónde aparece el valor medido? La API proporciona un mecanismo para monitorizar las mediciones realizadas:



const obs = new PerformanceObserver((items) => {
   console.log(items.getEntries());
 });

obs.observe({ entryTypes: ['measure'] });

Lo cuál escribiría en pantalla lo siguiente:



[
  PerformanceEntry {
    name: 'slowFunc',
    entryType: 'measure',
    startTime: 36.153894,
    duration: 999.870955
  }
]
[
  PerformanceEntry {
    name: 'div',
    entryType: 'measure',
    startTime: 36.186445,
    duration: 999.804569
  }
]

Notad cómo este mecanismo es mucho más potente que el console.time ya que nos permite gestionar por código las mediciones. Es decir, podemos recoger los valores medidos, almacenarlos, procesarlos, etc.

Tiempo de ejecución de una función

Otro mecanismo que nos ofrece la Performance API es timerify. Se trata de sustituir la llamada de la función a medir por un wrapper que incorpora mediciones de rendimiento. Así, donde antes teníamos una llamada a dummy(), ahora llamaremos a otra función, llamémosla dummy_timerify, que abremos obtenido de la siguiente forma:



const dummy_timerify = performance.timerify(dummy);

Para la obtención de los resultados del análisis usamos el mismo mecanismo basado en callbacks visto en el punto anterior. Nuestro código de ejemplo quedaría de la siguiente manera:



const { PerformanceObserver, performance } = require('perf_hooks');

const obs = new PerformanceObserver((items) => {
   console.log(items.getEntries());
   //performance.clearMarks();
 });

obs.observe({ entryTypes: ['function'] });


const add = (a, b) => {
   return a+b
}

const div = (a, b) => {
   const startAt = new Date();
   if (b === 0) {
      throw Error;
   }

   // code to consume CPU cycles
   while (Date.now() - startAt < 1000) {}

   return a/b;
}

const slowFunc = (a, b) => {
   const sum = add(a, b);

   const result = div_timerify(sum, 10);
}

const div_timerify = performance.timerify(div);

slowFunc(10, 20);

Notemos lo siguiente:

a la función observe hay que pasarle function, como entryType, en lugar de measure
se trata de un mecanismo invasivo. Otra vez es necesario añadir código a propósito de la medición. Sin embargo, a diferencia de los anteriores, el impacto es menor ya que solo es necesario modificar la línea de la llamada a la función de interés. De hecho se podría llegar a evitar usando una inyección de dependencias, por ejemplo si la llamada la paremetrizamos en una configuración inicial.

El resultado que veríamos en pantalla es (notad cómo también se incluyen los valores pasados como parámetros a la función, 30 y 10 en este caso):



[ PerformanceEntry {
    '0': 30,
    '1': 10,
    name: 'div',
    entryType: 'function',
    startTime: 67.022801,
    duration: 999.952593 } ]

NodeJS profiler

NodeJS inluye un profiler nativo. Para emplearlo es necesario ejecutar la aplicación en modo profiler. En este paso la aplicación se ejecutará normalmente y además creará un fichero con información sobre la ejecución. Dicho fichero no es interpretable directamente, por lo que es necesario transformarlo. El siguiente fragmento de código muestra el proceso completo:



node --prof perf_profile.js
node --prof-process isolate-0x27c5960-v8.log > processed.txt

El fichero generado tiene una apariencia similar a este:



 [JavaScript]:
   ticks  total  nonlib   name
    395   38.7%   47.6%  Builtin: GetProperty
     44    4.3%    5.3%  Builtin: Subtract
     28    2.7%    3.4%  Builtin: OrdinaryToPrimitive_Number
     23    2.3%    2.8%  LazyCompile: *div /home/andres/blog/perf_profile.js:5:13
     15    1.5%    1.8%  Builtin: NonNumberToNumeric
     10    1.0%    1.2%  Builtin: NonPrimitiveToPrimitive_Number
      9    0.9%    1.1%  Builtin: CallFunction_ReceiverIsNotNullOrUndefined
      8    0.8%    1.0%  Builtin: CEntry_Return1_DontSaveFPRegs_ArgvOnStack_NoBuiltinExit
      6    0.6%    0.7%  Builtin: DatePrototypeValueOf
      4    0.4%    0.5%  Builtin: DatePrototypeToPrimitive
      4    0.4%    0.5%  Builtin: Call_ReceiverIsNotNullOrUndefined
      1    0.1%    0.1%  Builtin: StoreIC
      1    0.1%    0.1%  Builtin: LoadIC_Uninitialized

Y este es el resultado de otra aplicación, un poco más larga que la de ejemplo, donde se pueden ver las llamadas a métodos de la librería turfjs



 [JavaScript]:
   ticks  total  nonlib   name
  10109   13.8%   13.8%  LazyCompile: *bearing /home/andres/dev/outtrack/node_modules/@turf/turf/turf.js:7273:17
   9264   12.6%   12.7%  LazyCompile: *distance /home/andres/dev/outtrack/node_modules/@turf/turf/turf.js:4742:18
   7148    9.7%    9.8%  LazyCompile: *<anonymous> /home/andres/dev/outtrack/node_modules/@turf/turf/turf.js:9883:32
   3196    4.4%    4.4%  LazyCompile: *degreesToRadians /home/andres/dev/outtrack/node_modules/@turf/turf/turf.js:598:26
   2517    3.4%    3.4%  LazyCompile: *searchFirstBoundingBox /home/andres/dev/outtrack/gis.js:41:26
   2023    2.8%    2.8%  LazyCompile: *bearingToAzimuth /home/andres/dev/outtrack/node_modules/@turf/turf/turf.js:569:26
   1743    2.4%    2.4%  Builtin: CompileLazy
   1651    2.2%    2.3%  LazyCompile: *coordEach /home/andres/dev/outtrack/node_modules/@turf/turf/turf.js:832:19
   1641    2.2%    2.2%  LazyCompile: *getCoord /home/andres/dev/outtrack/node_modules/@turf/turf/turf.js:1755:18
   1616    2.2%    2.2%  LazyCompile: *<anonymous> /home/andres/dev/outtrack/node_modules/@turf/turf/turf.js:1518:42
   1227    1.7%    1.7%  LazyCompile: *<anonymous> /home/andres/dev/outtrack/node_modules/@turf/turf/turf.js:1379:32
   1006    1.4%    1.4%  LazyCompile: *getCoords /home/andres/dev/outtrack/node_modules/@turf/turf/turf.js:1780:19
    989    1.3%    1.4%  LazyCompile: *geomEach /home/andres/dev/outtrack/node_modules/@turf/turf/turf.js:1222:18
    865    1.2%    1.2%  LazyCompile: *searchBoundingBox /home/andres/dev/outtrack/gis.js:51:21
    844    1.2%    1.2%  LazyCompile: *feature /home/andres/dev/outtrack/node_modules/@turf/turf/turf.js:93:17
    767    1.0%    1.0%  LazyCompile: *<anonymous> /home/andres/dev/outtrack/node_modules/@turf/turf/turf.js:1508:35

Como se puede ver, la interpretación de este fichero no es trivial. Por ello han surgido herramientas que muestran la misma información de manera más visual. clinicjs es un buen ejemplo. Se trata de una suite de análisis de rendimiento que incluye varias herramientas:

clinic doctor, para el análisis de uso de CPU, memoria o retardo del event loop
clinick flame, que muestra un flamegraph, esto, una representación de las llamadas a funciones, donde en el eje Y se muestra el anidamiento de las mismas, y en el eje X el tiempo que se estuvieron ejecutando. Este tipo de gráfica es lo más paracido, en versión visual, a la Performance API

Complejidad algorítmica o cómo mejorar el tiempo de ejecución

Andrés Estévez — Sat, 21 Dec 2019 20:18:17 +0000

¿Deberíamos reimplementar nuestra aplicación, o parte de ella, en un lenguaje más rápido? ¿Tendríamos que dar más recursos a nuestras máquinas? ¿Habría, incluso, que plantear un cambio de arquitectura y optar por una que facilite el paralelismo? Todas ellas son preguntas que nos hemos planteado alguna vez, especialmente cuando nuestra aplicación incrementa el uso de recursos y el rendimiento del sistema se degrada. En este tipo de situaciones, antes de inclinarse por una opción u otra, conviene averiguar cuál es la raíz del problema proponer una solución que actúe sobre dicha raíz.

En este post se explora una de las causas que ralentizan nuestras aplicaciones: la complejidad algorítmica. ¿Cómo varía el tiempo de ejecución al variar el número de datos a procesar? ¿Y los recursos del sistema, como la RAM o CPU? Veremos que, en función de cómo aumente el tiempo de ejecución al incrementar el tamaño de los datos de entrada, tendremos que nuestro algoritmo se comporta de manera:

Constante: los recursos que emplea el algoritmo no dependen del tamaño de los datos
Lineal: los recursos necesarios aumentan de manera lineal al tamaño de los datos (ej.: el doble de datos, el doble de tiempo)
Logarítmico: el incremento de tiempo sigue una respuesta logarítmica
Cuadrático: los recursos incrementan de manera cuadrática con el número de elementos en el conjunto de datos de la entrada

Sin pérdida de generalidad veamos un ejemplo concreto: dado un array de números, se pide obtener los índices de par de números que suman un determinado valor. Si bien se trata de un ejemplo ilustrativo, es trasladable a una aplicación real. Los casos donde tenemos que recorrer un array y relacionarlo con alguno o algunos de los demás elementos son muy comunes, por ejemplo, en procesado de imágenes, procesado de datos de información geográfica, algoritmos de compresión, etc.

Partamos del siguiente array:

[1, 2, 3, 5]

si el valor buscado es el 7 la solución será (1, 3), ya que el 2 y el 5 son los únicos elementos que suman 7. ¿Cuál sería la lógica del algoritmo para resolver este problema? Veamos varias alternativas y analicemos cuál es su rendimiento.

A menudo la primera opción que se nos ocurre para este tipo de problemas es la llamada comúnmemente fuerza bruta y consiste en analizar todas las combinaciones posibles. Para cada elemento del array, que llamaremos elemento de referencia, buscaremos si hay algún número que sume 7 con el número de referencia. Para el caso que nos ocupa:

empezamos con el 1 como referencia y recorremos el resto de elementos buscando un 6, esto es, el complementario para que la suma de ambos sea 7

en la segunda iteración la referencia es 2, por lo que buscamos un 5, que encontraremos en la última posición del array.

function searchPairSimple(data, target) {
    for (i = 0; i < data.length; i++) {
        for (j = 0; j < data.length; j++) {
            if (i == j) continue;

            if (data[i] + data[j] === target) {
                return [i, j];
            }
        }
    }
}

Los tiempos de ejecución para esta solución en función del número de elementos del array son:

Tamaño	Algoritmo básico
250	0.64
500	0.75
1000	2.98
2000	12.03
4000	47.7

¿Cómo podemos mejorar el rendimiento de esta solución? Fijémonos en el segundo bucle. Empieza en el cero, lo que significa que se van a probar combinaciones que ya se habían probado. Por ejemplo, cuando la i valía 0 y la j 1, los valores que teníamos eran el 1 y 2, que suman 3, y por tanto no cumplen la condición buscada. Ahora bien, cuando la i vale 1 y la j vale 0, los valores vuelven a ser el 1 y el 2. Volver a probar pares que ya habían sido descartados es una pérdida de tiempo y recursos, ¿es posible evitarlo? Basta inicializar la j del segundo bucle al valor siguiente de la i. De esta manera las iteracciones se reducen a la mitad.

    function searchPairSimpleOptimized(data, target) {
        for (i = 0; i < data.length - 1; i++) {
            for (j = i+1; j < data.length; j++) {

                if (data[i] + data[j] === target) {
                    return [i, j];
                }    
            }
        }
    }

Tamaño	Algoritmo básico	Algoritmo microoptimizado
250	0.64	0.48
500	0.75	0.38
1000	2.98	1.47
2000	12.03	5.83
4000	47.7	23.27

¿Es posible mejorarlo aún más? Fijémonos en el último valor del array, el 5. Se ha leído tantas veces como longitud tiene el array, es decir, en cada pasada por el array lo estamos leyendo otra vez. Con el resto de número pasa algo similar: cuanto más a la derecha se encuentren, más veces se habrán leído. ¿Habría forma de leerlos una sola vez? Es decir, cuando estemos en cualquier posición del array, ¿podríamos saber si existe el número complementario sin necesidad de volver a recorrerlo? Dicho de otra forma, ¿podríamos memorizar el contenido del array para no tener que recorrerlo más? La respuesta es sí. Veamos el siguiente código:

function searchPairDictionary(data, target) {

    let dict = {}
    for (let i = 0; i < data.length; i++) {
        dict[data[i]] = i; 

        if (dict[ target - data[i] ] !== undefined && 
            dict[ target - data[i] ]  !== i) {

                return [i, dict[ target - data[i]]];
        }
    }
}

La idea es la siguiente: al mismo tiempo que recorremos el array vamos almacenando los valores leídos en un diccionario, cuya clave es el valor que hay en la posición actual del array, y el valor es el índice en el que se encuentra. ¿Por qué esta estructura? La clave es lo que usamos para buscar, mientras que el valor es lo que buscamos: la posición del elemento en el array. Así, cuando hayamos leído el valor 1 del array podremos 'preguntarle' al diccionario si tiene un 6. De esta forma ahorramos volver a iterar sobre todo el array.

Tamaño	Algoritmo básico	Algoritmo microoptimizado	Diccionario
250	0.64	0.48	0.1
500	0.75	0.38	0.1
1000	2.98	1.47	0.23
2000	12.03	5.83	0.54
4000	47.7	23.27	0.59

El tiempo de ejecución ha mejorado, especialmente cuando el tamaño del array crece. Además, comparándolo con los tiempos de las dos versiones anteriores del algoritmo la mejora es todavía mayor. Se trata pues, de un buen ejemplo, de cómo cambiando la lógica de nuestra aplicación es posible mejorar mucho el rendimiento sin necesidad de ampliar los recursos disponibles o de emplear arquitecturas software complejas. Si bien, esta mejora no ha sido a coste cero ya que, a diferencia de las otras soluciones, estamos empleando más memoria, la necesaria para el diccionario.

La siguiente imagen representa gráficamente la evolución de los tiempos:

Es buena práctica tener siempre en mente cuál es la complejidad algorítmica de nuestro código. La notación big O, que indica cuál es el orden de mágnitud máximo de nuestro algoritmo, es una de las más extendidas. Así, un algoritmo O(n^2) tardará, como mucho, el cuadrado del tiempo de ejecución de un elemento, pero podría ser menos. La siguiente gráfica muestra cómo evolucionan los tiempos de varios

(https://www.geeksforgeeks.org/analysis-algorithms-big-o-analysis/)