Profilage des applications Node.js

De nombreux outils tiers sont disponibles pour le profilage des applications Node.js, mais dans de nombreux cas, l'option la plus simple est d'utiliser le profileur intégré à Node.js. Le profileur intégré utilise le profileur interne de V8 qui échantillonne la pile à intervalles réguliers pendant l'exécution du programme. Il enregistre les résultats de ces échantillons, ainsi que des événements d'optimisation importants tels que les compilations JIT, sous forme d'une série de ticks :

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"

Auparavant, il fallait le code source de V8 pour pouvoir interpréter les ticks. Heureusement, des outils ont été introduits depuis Node.js 4.4.0 qui facilitent la consommation de ces informations sans avoir à compiler séparément V8 à partir de la source. Voyons comment le profileur intégré peut aider à fournir un aperçu des performances de l'application.

Pour illustrer l'utilisation du profileur de ticks, nous allons travailler avec une simple application Express. Notre application aura deux gestionnaires, l'un pour ajouter de nouveaux utilisateurs à notre système :

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)
})

et un autre pour valider les tentatives d'authentification des utilisateurs :

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)
  }
})

Veuillez noter que ce ne sont PAS des gestionnaires recommandés pour l'authentification des utilisateurs dans vos applications Node.js et qu'ils sont utilisés uniquement à des fins d'illustration. Vous ne devriez pas essayer de concevoir vos propres mécanismes d'authentification cryptographique en général. Il est bien meilleur d'utiliser des solutions d'authentification existantes et éprouvées.

Supposons maintenant que nous ayons déployé notre application et que les utilisateurs se plaignent d'une latence élevée sur les requêtes. Nous pouvons facilement exécuter l'application avec le profileur intégré :

NODE_ENV=production node --prof app.js

et mettre une certaine charge sur le serveur en utilisant 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"

et obtenir une sortie 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)

D'après cette sortie, nous voyons que nous ne réussissons à servir qu'environ 5 requêtes par seconde et que la requête moyenne prend un peu moins de 4 secondes aller-retour. Dans un exemple réel, nous pourrions effectuer beaucoup de travail dans de nombreuses fonctions pour le compte d'une requête utilisateur, mais même dans notre exemple simple, du temps pourrait être perdu à compiler des expressions régulières, à générer des salts aléatoires, à générer des hachages uniques à partir des mots de passe des utilisateurs, ou à l'intérieur du framework Express lui-même.

Puisque nous avons exécuté notre application en utilisant l'option --prof, un fichier de ticks a été généré dans le même répertoire que votre exécution locale de l'application. Il devrait avoir la forme isolate-0xnnnnnnnnnnnn-v8.log (où n est un chiffre).

Pour donner un sens à ce fichier, nous devons utiliser le processeur de ticks fourni avec le binaire Node.js. Pour exécuter le processeur, utilisez l'indicateur --prof-process :

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

L'ouverture de processed.txt dans votre éditeur de texte préféré vous donnera différents types d'informations. Le fichier est divisé en sections qui sont à nouveau divisées par langue. Tout d'abord, nous examinons la section récapitulative et voyons :

[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

Cela nous indique que 97 % de tous les échantillons recueillis se sont produits dans le code C++ et que lors de l'examen d'autres sections de la sortie traitée, nous devrions accorder la plus grande attention au travail effectué en C++ (par opposition à JavaScript). En gardant cela à l'esprit, nous trouvons ensuite la section [C++] qui contient des informations sur les fonctions C++ qui prennent le plus de temps CPU et voyons :

 [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

Nous voyons que les 3 premières entrées représentent 72,1 % du temps CPU pris par le programme. D'après cette sortie, nous voyons immédiatement qu'au moins 51,8 % du temps CPU est pris par une fonction appelée PBKDF2 qui correspond à notre génération de hachage à partir du mot de passe d'un utilisateur. Cependant, il n'est peut-être pas immédiatement évident de savoir comment les deux entrées inférieures entrent en jeu dans notre application (ou si c'est le cas, nous ferons semblant pour les besoins de l'exemple). Pour mieux comprendre la relation entre ces fonctions, nous allons ensuite examiner la section [Profil ascendant (lourd)] qui fournit des informations sur les appelants principaux de chaque fonction. En examinant cette section, nous trouvons :

  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

L'analyse de cette section demande un peu plus de travail que les nombres de ticks bruts ci-dessus. Dans chacune des « piles d'appels » ci-dessus, le pourcentage dans la colonne parent vous indique le pourcentage d'échantillons pour lesquels la fonction de la ligne ci-dessus a été appelée par la fonction de la ligne actuelle. Par exemple, dans la « pile d'appels » du milieu ci-dessus pour _sha1_block_data_order, nous voyons que _sha1_block_data_order s'est produit dans 11,9 % des échantillons, ce que nous savions d'après les nombres bruts ci-dessus. Cependant, ici, nous pouvons également dire qu'il a toujours été appelé par la fonction pbkdf2 dans le module crypto de Node.js. Nous voyons que de même, _malloc_zone_malloc a été appelé presque exclusivement par la même fonction pbkdf2. Ainsi, en utilisant les informations de cette vue, nous pouvons dire que notre calcul de hachage à partir du mot de passe de l'utilisateur représente non seulement les 51,8 % de la section précédente, mais également tout le temps CPU dans les 3 fonctions les plus échantillonnées, car les appels à _sha1_block_data_order et _malloc_zone_malloc ont été effectués pour le compte de la fonction pbkdf2.

À ce stade, il est très clair que la génération de hachage basée sur le mot de passe doit être la cible de notre optimisation. Heureusement, vous avez pleinement internalisé les avantages de la programmation asynchrone et vous réalisez que le travail de génération d'un hachage à partir du mot de passe de l'utilisateur est effectué de manière synchrone et lie donc la boucle d'événements. Cela nous empêche de travailler sur d'autres requêtes entrantes pendant le calcul d'un hachage.

Pour remédier à ce problème, vous apportez une petite modification aux gestionnaires ci-dessus pour utiliser la version asynchrone de la fonction 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)
    }
  })
})

Une nouvelle exécution du benchmark ab ci-dessus avec la version asynchrone de votre application donne :

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)

Génial ! Votre application sert maintenant environ 20 requêtes par seconde, soit environ 4 fois plus qu'avec la génération de hachage synchrone. De plus, la latence moyenne est passée de 4 secondes à un peu plus d'une seconde.

Espérons que, grâce à l'investigation des performances de cet exemple (admettons artificiel), vous avez vu comment le processeur de ticks V8 peut vous aider à mieux comprendre les performances de vos applications Node.js.

Vous pouvez également trouver comment créer un graphique de flamme utile.