Explorando el API Performance Timeline

Os invitamos a profundizar en las nuevas posibilidades que nos ofrece el API Performance Timeline, el estándar de la W3C para el análisis de rendimiento. El propósito de este API es la recopilación de marcas de tiempo de alta precisión.

Ya en varias ocasiones hemos tratado en TodoJS.com la forma de analizar la velocidad del código Javascript, desde la librería BenchmarkJS para comparar el rendimiento de dos funciones, a las capacidades de tiempo de alta precisión en Javascript.

En este artículo vamos a dar un repaso a algunas de las funcionalidades del API de Performance Timeline, en especial las que ya han sido implementadas en Node (a partir de la versión 8.5.0) en el paquete estándar perf_hooks y que paulatinamente vamos encontrando en los navegadores. Ofrecen una forma muy completa de medir el rendimiento del código por medio de un API estándar.

Librería perf_hooks

Node ha incluido el API Performance Time en el paquete estándar perf_hooks. Los navegadores por su parte incluyen el objeto en window.performance, por lo que no requiere de carga alguna. En Node sólo tenemos que hacer uso de require() (o import, si tenemos habilitada esta instrucción en modo experimental) para cargar este paquete estándar.

const perf = require('perf_hooks');

performance.now()

El primer objeto de esta librería al que nos vamos a referir es performance y el método más habitualmente utilizado de este objeto es now() que devuelve una referencia temporal de alta precisión.

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

const start = performance.now();
const unique = new Set();
while (unique.size < 1000000) {
  unique.add (Math.random ().toString (16).substring (2));
}
const end = performance.now();
console.log(end - start);

Una gran ventaja de este método es que está disponible en IE10, Firefox 15, Chrome 24, Safari 8 y Node 8.5. Las llamadas a performance.now() devuelven un valor de milisegundos, con decimales, con una precisión de milésima de milisegundo (millonesima parte de un segundo, o nanosegundo). ´

El valor devuelto está referenciado al inicio de nuestro programa, no es una fecha y hora como tal, y por lo tanto sólo es útil si la utilizamos como marca de tiempo. Además de la ventaja de su precisión, tiene la característica de que los valores devueltos son monótonamente crecientes, es decir, que no están afectados por los ajustes o desviación del reloj del sistema. Dicho de otra forma, la diferencia entre dos valores obtenidos de performance.now() nunca puede ser negativa.

PerformanceObserver

Para sacar todo el partido a esta librería es conveniente que importemos otro elemento adicional de perf_hooks, denominado PerformanceObserver. Esta clase nos va a permitir definir una función callback que será invocada de forma automática cuando se vayan insertando las medidas en el registro. Básicamente lo que vamos a hacer es incluir estas líneas:

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

const obs = new PerformanceObserver((timeline) => {
  obs.disconnect();
  console.log(timeline.getEntries());
});
obs.observe({ entryTypes: ['mark'], buffered: true});

Vamos a explicar paso a paso lo que hemos incluido:

• Hemos importado la clase PerformanceObserver del paquete perf_hook
• Hemos instanciado un objeto de esta clase, pasando una función al constructor.
• Como es importante cancelar las suscripción en cuanto sea posible, se ha llamado a obs.disconnect() cuando ya no es necesarias la suscripción.
• Esta función recibirá un objeto *timeline* del que extraeremos los valores de las medidas realizadas que obtenemos con .getEntries().
• Del objeto devuelto por new PerformanceObserver() utilizamos el método .observe() pasando un objeto de configuración:
  • por medio de la propiedad entryTypes indicamos qué queremos observar (veremos enseguida que significa esto)
  • por medio de la propiedad buffered pedimos que los resultados se vayan almacenando en un buffer hasta que se libere el bucle de eventos (similar a cuando se llama a setImmediate()).

Todavía no estamos midiendo nada, seguramente la impaciencia va en aumento, pero estas primeras líneas son necesarias para todo lo que viene a continuación.

performance.mark()

El primer tipo de medición que podemos hacer es mark, para ello realizamos llamadas a performance.mark("nombre") en nuestro código. Esto crea entradas en el registro de tiempos de la librería:

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

const obs = new PerformanceObserver((timeline) => {
  obs.disconnect();
  console.log(timeline.getEntries());
});
obs.observe({ entryTypes: ['mark'], buffered: true});

performance.mark ('start');
const unique = new Set ();
while (unique.size < 1000000) {
  unique.add (Math.random ().toString (16).substring (2));
}
performance.mark ('end');

El resultado de este programa se muestra por consola y será más o menos de este tipo:

[
  {
    name     : 'start',
    entryType: 'mark',
    startTime: 127.2762,
    duration : 0
  },
  {
    name     : 'end',
    entryType: 'mark',
    startTime: 1843.9068,
    duration : 0
  }
]

Como vemos, se han creado dos entradas, cada una con su nombre, las dos de tipo mark y con un startTime, que corresponde a los milisegundos desde que se inició el programa que estamos ejecutando.

Como este mecanismo podemos crear cuantas entradas queramos para ir controlando diferentes puntos de nuestro programa:

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

const obs = new PerformanceObserver((timeline) => {
  obs.disconnect();
  console.log(timeline.getEntries());
});
obs.observe({ entryTypes: ['mark'], buffered: true});

performance.mark ('start');
const unique = new Set ();
performance.mark ('start loop');
while (unique.size < 1000000) {
  unique.add (Math.random ().toString (16).substring (2));
}
performance.mark ('end loop');
performance.mark ('end');

El resultado será:

[
  {
    name     : 'start',
    entryType: 'mark',
    startTime: 106.4997,
    duration : 0
  },
  {
    name     : 'start loop',
    entryType: 'mark',
    startTime: 107.059799,
    duration : 0
  },
  {
    name     : 'end loop',
    entryType: 'mark',
    startTime: 1792.981,
    duration : 0
  },
  {
    name     : 'end',
    entryType: 'mark',
    startTime: 1793.022,
    duration : 0
  }
]

performance.measure()

El trabajo con marks es bastante interesante, pero en muchas ocasiones nos interesa conocer el tiempo entre dos marcas, y a eso se le llama measure, que es otro tipo de entrada en el registro de tiempos. En este caso tenemos que llamar a performance.measure("nombre", "marca_inicio", "marca_fin") para crear estos nuevos registros.

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

const obs = new PerformanceObserver((timeline) => {
  obs.disconnect();
  console.log(timeline.getEntries());
});
obs.observe({ entryTypes: ['measure'], buffered: true});

const unique = new Set ();
performance.mark ('start loop');
while (unique.size < 1000000) {
  unique.add (Math.random ().toString (16).substring (2));
}
performance.mark ('end loop');
performance.measure ('loop', 'start loop', 'end loop');

El resultado será similar a este:

[
  {
    name     : 'loop',
    entryType: 'measure',
    startTime: 137.7393,
    duration : 1628.7361
  }
]

Es importante fijarse que hemos cambiado el valor de entryTypes y hemos incluido measure. Ahora recibimos las entradas de tipo measure y hemos dejado de recibir las de tipo mark. Ahora en los datos hay valores para la propiedad duraction.

Podemos ir un paso más allá, y en vez de medir lo que tarda todo el bucle, medir cuanto se tarda en ejecutar cada línea dentro del bucle. Recordemos que estas medidas son de alta precisión y pueden registrar tiempos verdaderamente pequeños de ejecución con una gran fiabilidad. Para ello movemos de sitio las marcas y la creación de la medida.

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

const obs = new PerformanceObserver ((timeline) => {
  obs.disconnect ();
  console.log (timeline.getEntries ());
});
obs.observe ({entryTypes : [ 'measure' ], buffered : true});

const unique = new Set ();
while (unique.size < 100) {
  performance.mark ('start instruction');
  unique.add (Math.random ().toString (16).substring (2));
  performance.mark ('end instruction');
  performance.measure ('instruction', 'start instruction', 'end instruction');
}

El resultado será una entrada por cada ejecución, con el tiempo en el que se ha iniciado y la duración de la ejecución.

[
  {
    "name"     : "instruction",
    "entryType": "measure",
    "startTime": 134.7327,
    "duration" : 0.3067
  },
  {
    "name"     : "instruction",
    "entryType": "measure",
    "startTime": 135.9404,
    "duration" : 0.025099
  },
  {
    "name"     : "instruction",
    "entryType": "measure",
    "startTime": 136.0395,
    "duration" : 0.0066
  }, //...continue

performance.timerify()

Si lo que queremos es medir el tiempo que tarda en ejecutarse una función, Node nos ofrece una sencilla utilidad performance.timerify() para obtener una versión supervisada de la función original, donde se va a registrar el tiempo de cada llamada, en este caso con el tipo function.

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

const obs = new PerformanceObserver ((timeline) => {
  obs.disconnect ();
  console.log (timeline.getEntries ());
});
obs.observe ({entryTypes : [ 'function' ], buffered : true});

const unique    = new Set ();
const addUnique = performance.timerify (function addUnique () {
  unique.add (Math.random ().toString (16).substring (2));
});

while (unique.size < 100000) {
  addUnique ()
}

El resultado de este tipo:

[
  {
    name     : 'addUnique',
    entryType: 'function',
    startTime: 92.2212,
    duration : 0.1677
  },
  {
    name     : 'addUnique',
    entryType: 'function',
    startTime: 92.8332,
    duration : 0.008401
  },
  {
    name     : 'addUnique',
    entryType: 'function',
    startTime: 92.8781,
    duration : 0.002001
  }, //...continue

Como podemos ver, las entradas son ahora de tipo function y tiene como nombre el nombre de la función que hemos pasado a performance.timerify(). Si es una función anónima, entonces será ''. Esta forma abreviada es muy práctica, ya que hace el recubrimiento de una función de forma muy sencilla y sin necesidad de generar varias marcas para luego agruparlas en una medida.

Observar varios tipos de registros y diferenciarlos

Seguramente algunos os habréis dado cuenta que entryTypes es una matriz, lo cual nos puede hacer pensar que podemos recibir registros de varios tipos. Así es, si ponemos ['function', 'measures'] recibiremos registros de estos dos tipos.

Nosotros hemos obtenidos todos los registros con .getEntries(), pero también podemos utilizar .getEntriesByName (nombre [, tipo]) y getEntriesByType (tipo) para obtener sólo los registros que nos interesan.

Como ejercicio para los más curiosos os animamos a explorar otros tipos de registros que guardan automáticamente información como son node para las llamadas internas de node, gc para el recolector de basura o http2.

Analizar estadísticamente los resultados

Es fácil que el número de registros en la línea de tiempo sea bastante elevado y que la matriz de entradas pueda abrumarnos un poco. Difícilmente podremos obtener datos valiosos de una sola ejecución del código y debemos someter a un cierto estrés nuestro programa, ejecutando miles o millones de veces la parte de código que queremos analizar y de esta forma eliminar la variación que puede sufrir el código Javascript en una ejecución puntual.

Para simplificar el análisis de este conjunto de datos podemos crear una pequeña utilidad que permita obtener datos estadísticos más interesantes sobre la ejecución. En el siguiente ejemplo, hemos preparado un informe en el que para cada nombre de entrada devuelva:

• Número de ejecuciones
• Tiempo total acumulado en las ejecuciones
• Tiempo medio de ejecución
• Desviación típica del tiempo de ejecución
• Tiempo mínimo de ejecución
• Tiempo máximo de ejecución
• Percentiles del tiempo de ejecución (una matriz con 100 entradas)

Veamos el código para generar estas estadísticas y su aplicación a uno de los ejemplos anteriores:

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

const obs = new PerformanceObserver ((timeline) => {
  obs.disconnect ();
  console.log (entriesStatistics (timeline.getEntries ()));
});
obs.observe ({entryTypes : [ 'measure' ], buffered : true});

const unique = new Set ();
while (unique.size < 100000) {
  performance.mark ('start instruction');
  unique.add (Math.random ().toString (16).substring (2));
  performance.mark ('end instruction');
  performance.measure ('instruction', 'start instruction', 'end instruction');
}

function entriesStatistics (entries) {
  if (entries.length === 0) {
    return {}
  }
  const names = {};
  for (let entry of entries) {
    const e = names[ entry.name ]  || (names[ entry.name ] = {count : 0, sum : 0});
    e.count++;
    e.sum += entry.duration;
  }
  for (let name of Object.keys (names)) {
    const e = names[ name ];
    e.avg   = e.sum / e.count;
    e.sdiff = 0;
  }
  for (let entry of entries) {
    names[ entry.name ].sdiff += entry.duration - names[ entry.name ].avg ** 2;
  }
  for (let name of Object.keys (names)) {
    const e            = names[ name ];
    const sortDuration = entries
      .filter (x => x.name === name)
      .map (x => x.duration)
      .sort ((x, y) => x - y);
    e.stddev           = Math.sqrt (e.sdiff / e.count);
    e.min              = sortDuration[ 0 ];
    e.max              = sortDuration[ sortDuration.length - 1 ];
    e.percentiles      = [];
    const onePercent   = Math.floor (e.count / 100);
    for (let p = 0; p < 99; p++) {
      e.percentiles[ p ] = sortDuration[ onePercent * p ];
    }
    e.percentiles[ 99 ]  = e.max;
    delete e.sdiff;
  }
  return names;
}

El resultado es este resumen:

{
  instruction: {
    count             : 100000,
    sum               : 477.8434889999771,
    avg               : 0.004778434889999772,
    stddev            : 0.08474235242810547,
    min               : 0.001999,
    max               : 19.3176,
    percentiles       : [0.001999, 0.0022, 0.002201, 0.002299, 0.0023, 0.0023, ...]
  }
}

Os animamos a explorar las posibilidades de análisis que ofrecen los registros almacenados, con un poco de cálculo podréis crear vuestros propios análisis y generar informes que puedan ofrecer información interesante para vuestros propósitos.

Conclusiones

La aparición de el API Performance Timeline y su implementación en Node -y en los diferentes navegadores- es un gran avance para los que tenemos que trabajar con tiempos de respuesta muy pequeños y necesitamos optimizar nuestro código hasta prácticamente el límite. Posiblemente esta no es la situación en la que se encuentran la mayoría de los programadores y es mejor dejar las optimizaciones para situaciones verdaderamente comprometidas, evitando la sobre optimización prematura que en ocasiones se realizamos.

En todo caso, tenemos a nuestra disposición herramientas estándar, sencillas, prácticas y precisas para analizar el rendimiento de nuestro código que nos hacen la vida más fácil a la hora de abordar el análisis del rendimiento del código.

Esperamos que se haya abierto vuestra curiosidad y os animamos a explorar aun con mayor profundidad las capacidades de este API con este taller práctico donde profundizamos sobre perf_hooks en Node que organizó el grupo de Meetup Madrid Node JS.