Análisis de rendimiento de aplicaciones Node.js

Existen muchas herramientas de terceros disponibles para el análisis de rendimiento de aplicaciones Node.js, pero en muchos casos, la opción más sencilla es usar el analizador de rendimiento integrado de Node.js. El analizador integrado usa el analizador dentro de V8, el cual muestrea la pila a intervalos regulares durante la ejecución del programa. Registra los resultados de estas muestras, junto con eventos importantes de optimización como compilaciones JIT, como una serie de marcas:

code-creation,LazyCompile,0,0x2d5000a337a0,396,"bp native array.js:1153:16",0x289f644df68,~
code-creation,LazyCompile,0,0x2d5000a33940,716,"hasOwnProperty native v8natives.js:198:30",0x289f64438d0,~
code-creation,LazyCompile,0,0x2d5000a33c20,284,"ToName native runtime.js:549:16",0x289f643bb28,~
code-creation,Stub,2,0x2d5000a33d40,182,"DoubleToIStub"
code-creation,Stub,2,0x2d5000a33e00,507,"NumberToStringStub"

Anteriormente, se necesitaba el código fuente de V8 para poder interpretar las marcas. Afortunadamente, se han introducido herramientas desde Node.js 4.4.0 que facilitan el consumo de esta información sin necesidad de compilar V8 por separado desde la fuente. Veamos cómo el analizador integrado puede ayudar a proporcionar información sobre el rendimiento de la aplicación.

Para ilustrar el uso del analizador de marcas, trabajaremos con una aplicación Express simple. Nuestra aplicación tendrá dos manejadores, uno para agregar nuevos usuarios a nuestro sistema:

app.get('/newUser', (req, res) => {
  let username = req.query.username || ''
  const password = req.query.password || ''
  username = username.replace(/[!@#$%^&*]/g, '')
  if (!username || !password || users[username]) {
    return res.sendStatus(400)
  }
  const salt = crypto.randomBytes(128).toString('base64')
  const hash = crypto.pbkdf2Sync(password, salt, 10000, 512, 'sha512')
  users[username] = { salt, hash }
  res.sendStatus(200)
})

y otro para validar los intentos de autenticación del usuario:

app.get('/auth', (req, res) => {
  let username = req.query.username || ''
  const password = req.query.password || ''
  username = username.replace(/[!@#$%^&*]/g, '')
  if (!username || !password || !users[username]) {
    return res.sendStatus(400)
  }
  const { salt, hash } = users[username]
  const encryptHash = crypto.pbkdf2Sync(password, salt, 10000, 512, 'sha512')
  if (crypto.timingSafeEqual(hash, encryptHash)) {
    res.sendStatus(200)
  } else {
    res.sendStatus(401)
  }
})

Tenga en cuenta que estos NO son manejadores recomendados para autenticar usuarios en sus aplicaciones Node.js y se utilizan únicamente con fines ilustrativos. En general, no debe intentar diseñar sus propios mecanismos de autenticación criptográfica. Es mucho mejor usar soluciones de autenticación existentes y probadas.

Ahora supongamos que hemos desplegado nuestra aplicación y los usuarios se quejan de alta latencia en las solicitudes. Podemos ejecutar fácilmente la aplicación con el analizador integrado:

NODE_ENV=production node --prof app.js

y poner algo de carga en el servidor usando ab (ApacheBench):

curl -X GET "http://localhost:8080/newUser?username=matt&password=password"
ab -k -c 20 -n 250 "http://localhost:8080/auth?username=matt&password=password"

y obtener una salida ab de:

Concurrency Level:      20
Time taken for tests:   46.932 seconds
Complete requests:      250
Failed requests:        0
Keep-Alive requests:    250
Total transferred:      50250 bytes
HTML transferred:       500 bytes
Requests per second:    5.33 [#/sec] (mean)
Time per request:       3754.556 [ms] (mean)
Time per request:       187.728 [ms] (mean, across all concurrent requests)
Transfer rate:          1.05 [Kbytes/sec] received
...
Percentage of the requests served within a certain time (ms)
  50%   3755
  66%   3804
  75%   3818
  80%   3825
  90%   3845
  95%   3858
  98%   3874
  99%   3875
 100%   4225 (longest request)

De esta salida, vemos que solo estamos logrando servir alrededor de 5 solicitudes por segundo y que la solicitud promedio tarda casi 4 segundos de ida y vuelta. En un ejemplo del mundo real, podríamos estar haciendo mucho trabajo en muchas funciones en nombre de una solicitud de usuario, pero incluso en nuestro ejemplo simple, se podría perder tiempo compilando expresiones regulares, generando sales aleatorias, generando hashes únicos a partir de contraseñas de usuario, o dentro del propio framework Express.

Dado que ejecutamos nuestra aplicación usando la opción --prof, se generó un archivo de marcas en el mismo directorio que la ejecución local de la aplicación. Debería tener la forma isolate-0xnnnnnnnnnnnn-v8.log (donde n es un dígito).

Para darle sentido a este archivo, necesitamos usar el procesador de marcas incluido con el binario de Node.js. Para ejecutar el procesador, use la bandera --prof-process:

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

Abrir processed.txt en su editor de texto favorito le dará algunos tipos diferentes de información. El archivo se divide en secciones que a su vez se dividen por idioma. Primero, miramos la sección de resumen y vemos:

[Summary]:
   ticks  total  nonlib   name
     79    0.2%    0.2%  JavaScript
  36703   97.2%   99.2%  C++
      7    0.0%    0.0%  GC
    767    2.0%          Shared libraries
    215    0.6%          Unaccounted

Esto nos dice que el 97% de todas las muestras recopiladas ocurrieron en código C++ y que al ver otras secciones de la salida procesada, debemos prestar más atención al trabajo que se realiza en C++ (en lugar de JavaScript). Con esto en mente, a continuación encontramos la sección [C++] que contiene información sobre qué funciones C++ están tomando la mayor cantidad de tiempo de CPU y vemos:

 [C++]:
   ticks  total  nonlib   name
  19557   51.8%   52.9%  node::crypto::PBKDF2(v8::FunctionCallbackInfo<v8::Value> const&)
   4510   11.9%   12.2%  _sha1_block_data_order
   3165    8.4%    8.6%  _malloc_zone_malloc

Vemos que las 3 entradas principales representan el 72.1% del tiempo de CPU empleado por el programa. A partir de esta salida, vemos inmediatamente que al menos el 51.8% del tiempo de CPU lo ocupa una función llamada PBKDF2 que corresponde a nuestra generación de hash a partir de la contraseña de un usuario. Sin embargo, puede que no sea inmediatamente obvio cómo las dos entradas inferiores influyen en nuestra aplicación (o si lo es, lo haremos como si no lo fuera por el bien del ejemplo). Para comprender mejor la relación entre estas funciones, a continuación, veremos la sección [Perfil ascendente (pesado)], que proporciona información sobre los llamadores principales de cada función. Al examinar esta sección, encontramos:

  ticks parent  name
  19557   51.8%  node::crypto::PBKDF2(v8::FunctionCallbackInfo<v8::Value> const&)
  19557  100.0%    v8::internal::Builtins::~Builtins()
  19557  100.0%      LazyCompile: ~pbkdf2 crypto.js:557:16
   4510   11.9%  _sha1_block_data_order
   4510  100.0%    LazyCompile: *pbkdf2 crypto.js:557:16
   4510  100.0%      LazyCompile: *exports.pbkdf2Sync crypto.js:552:30
   3165    8.4%  _malloc_zone_malloc
   3161   99.9%    LazyCompile: *pbkdf2 crypto.js:557:16
   3161  100.0%      LazyCompile: *exports.pbkdf2Sync crypto.js:552:30

Analizar esta sección requiere un poco más de trabajo que los recuentos de marcas sin procesar anteriores. Dentro de cada una de las "pilas de llamadas" anteriores, el porcentaje en la columna de padres le indica el porcentaje de muestras para las cuales la función en la fila superior fue llamada por la función en la fila actual. Por ejemplo, en la pila de llamadas intermedia anterior para _sha1_block_data_order, vemos que _sha1_block_data_order ocurrió en el 11.9% de las muestras, lo que sabíamos por los recuentos sin procesar anteriores. Sin embargo, aquí también podemos decir que siempre fue llamada por la función pbkdf2 dentro del módulo crypto de Node.js. Vemos que, de manera similar, _malloc_zone_malloc fue llamada casi exclusivamente por la misma función pbkdf2. Por lo tanto, utilizando la información de esta vista, podemos decir que nuestro cálculo de hash a partir de la contraseña del usuario representa no solo el 51.8% de arriba, sino también todo el tiempo de CPU en las 3 funciones más muestreadas, ya que las llamadas a _sha1_block_data_order y _malloc_zone_malloc se realizaron en nombre de la función pbkdf2.

En este punto, está muy claro que la generación de hash basada en contraseña debe ser el objetivo de nuestra optimización. Afortunadamente, ha interiorizado completamente los beneficios de la programación asincrónica y se da cuenta de que el trabajo para generar un hash a partir de la contraseña del usuario se está realizando de forma sincrónica y, por lo tanto, atando el bucle de eventos. Esto nos impide trabajar en otras solicitudes entrantes mientras calculamos un hash.

Para remediar este problema, realiza una pequeña modificación a los manejadores anteriores para usar la versión asincrónica de la función pbkdf2:

app.get('/auth', (req, res) => {
  let username = req.query.username || ''
  const password = req.query.password || ''
  username = username.replace(/[!@#$%^&*]/g, '')
  if (!username || !password || !users[username]) {
    return res.sendStatus(400)
  }
  crypto.pbkdf2(password, users[username].salt, 10000, 512, 'sha512', (err, hash) => {
    if (users[username].hash.toString() === hash.toString()) {
      res.sendStatus(200)
    } else {
      res.sendStatus(401)
    }
  })
})

Una nueva ejecución del punto de referencia ab anterior con la versión asincrónica de su aplicación produce:

Concurrency Level:      20
Time taken for tests:   12.846 seconds
Complete requests:      250
Failed requests:        0
Keep-Alive requests:    250
Total transferred:      50250 bytes
HTML transferred:       500 bytes
Requests per second:    19.46 [#/sec] (mean)
Time per request:       1027.689 [ms] (mean)
Time per request:       51.384 [ms] (mean, across all concurrent requests)
Transfer rate:          3.82 [Kbytes/sec] received
...
Percentage of the requests served within a certain time (ms)
  50%   1018
  66%   1035
  75%   1041
  80%   1043
  90%   1049
  95%   1063
  98%   1070
  99%   1071
 100%   1079 (longest request)

¡Bien! Su aplicación ahora está sirviendo alrededor de 20 solicitudes por segundo, aproximadamente 4 veces más de lo que era con la generación de hash sincrónica. Además, la latencia promedio ha bajado de los 4 segundos anteriores a poco más de 1 segundo.

Con suerte, a través de la investigación de rendimiento de este ejemplo (ciertamente artificial), ha visto cómo el procesador de marcas V8 puede ayudarlo a comprender mejor el rendimiento de sus aplicaciones Node.js.

También puede encontrar cómo crear un gráfico de llama útil.