Profiler son application NodeJS

Je me suis essayé à un exercice dont je n’ai pas l’habitude: faire du profilage d’applications. Je n’en ai généralement pas eu besoin, les bottlenecks étant souvent faciles à identifier dans les applications sur lesquelles j’ai travaillé, mais viendra tôt ou tard le jour où on se demande si on ne peut pas simplement « faire mieux ». Il n’y a pas de problème particulier, pas d’URL ou de fonction spécifiquement lente identifiée, et dans ce cas si on veut améliorer les performances il faut qu’on trouve déjà où ça pourrait être amélioré 😉

Je pars d’assez loin, ma seule expérience tient dans XDebug et KCachegrind avec PHP. Expérience plutôt concluante d’ailleurs.

Le paysage est beaucoup moins rose du côté de Node.JS, d’une part à cause du peu d’outils « finis » disponibles. Pour résumer, la plupart des outils que j’ai trouvés me semblent plus utiles aux développeurs de V8 qu’au développeur JavaScript… Si vous avez la flemme de lire ce roman, vous pouvez passer directement à la conclusion où vous trouverez un tableau récapitulatif absolument subjectif 😉

Sommaire

Avertissement

Je préviens les pro du profiling qu’il y aura dans cet article de probables énormités sans doute impardonnables. Je vous demande deux choses: aidez-moi à corriger ces énormités :) mais prenez quand-même le temps de vulgariser à destination des débutants (m’incluant) 😉

Le profilage statistique

Tout d’abord il existe une notion que j’avais manipulé sans la connaître ni la comprendre auparavant: le profilage statistique.

Si on ne connait pas le principe, on ne comprend strictement rien à la sortie des différents outils testés, je l’ai appris en posant modestement la question (il n’y a pas de question idiote, il ne faut jamais en douter):

In any case with with statistical profiler « function Foo takes X ticks out of Y ticks recorded total » should be read as « profiler looked at the program Y times and in X times he saw function Foo near the top of the stack ». Statistical profiler results do not translate into information about event loop blocking or CPU cycles spent by functions.

Le profileur prend un instantané de l’état de la stack chaque milliseconde, et ça ne donne donc pas des stats de CPU ou de temps réel de traitement, mais plutôt du temps qu’a passé chaque fonction à tel endroit de la stack. Je suis loin d’avoir saisi les différents cas pratiques d’interprétation, et je vous serais infiniment reconnaissant si vous avez des ressources simples et pratiques sur le sujet, parce que ça semble être un de ces sujets que les spécialistes n’aiment pas vulgariser…

Bref, ça permet quand-même d’avoir un bon aperçu et ça peut naïvement se transposer à du temps CPU avec tout de même une certaine justesse. Et de toute façon même si ce n’est pas juste, ça donnera au moins les endroits dans lequel l’application passe le plus clair de son temps, donc gagner 1 ms à cet endroit ne peut être que bénéfique.

Le cas pratique

Pour se faire la main, j’ai testé les profileurs sur deux implémentations naïves d’un serveur HTTP affichant une valeur de la suite de Fibonacci (le bon vieux troll :P). L’idée étant que le profileur m’aide à voir que j’ai du boulot à cet endroit.

Première implémentation synchrone naïve:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
require('http').createServer(onRequest).listen(33331);
 
function onRequest(req, res) {
    if (req.url === '/hello') {
        respond(res, 200, 'Hello, world');
    } else if (req.url.match(/^\/(\d+)$/)) {
        respond(res, 200, fibo_sync(parseInt(req.url.substring(1))));
    } else {
        respond(res, 404, 'Not Found');
    }
}
 
function respond(res, status, content) {
  res.writeHead(status, {"Content-Type": "text/plain"});
  res.end(String(content));
}
 
function fibo_sync(n) {
  if (n === 0) {
    return 0;
  } else if (n === 1) {
    return 1;
  } else {
    return fibo_sync(n-1) + fibo_sync(n-2);
  }
}

Deuxième implémentation qui fait semblant d’être asynchrone (en fait elle bloquera bien sûr tout autant le CPU, mais devrait mieux distribuer les étapes du calcul dans le temps si d’autres instructions viennent s’intercaler):

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
require('http').createServer(onRequest).listen(33332);
 
function onRequest(req, res) {
    if (req.url === '/hello') {
        respond(res, 200, 'Hello, world');
    } else if (req.url.match(/^\/(\d+)$/)) {
        fibo_async(parseInt(req.url.substring(1)), respond.bind(null, res, 200));
    } else {
        respond(res, 404, 'Not Found');
    }
}
 
function respond(res, status, content) {
  res.writeHead(status, {"Content-Type": "text/plain"});
  res.end(String(content));
}
 
function fibo_async(n, cb) {
  if (n === 0) {
    process.nextTick(cb.bind(null, 0));
  } else if (n === 1) {
    process.nextTick(cb.bind(null, 1));
  } else {
    var n1, n2;
    function next1(n) {
        if (typeof n2 === 'undefined') {
            n1 = n;
        } else {
            process.nextTick(cb.bind(null, n+n2));
        }
    }
    function next2(n) {
        if (typeof n1 === 'undefined') {
            n2 = n;
        } else {
            process.nextTick(cb.bind(null, n1+n));
        }
    }
    process.nextTick(fibo_async.bind(null, n-1, next1));
    process.nextTick(fibo_async.bind(null, n-2, next2));
  }
}

Dans les deux cas on donnera un coup d’ab pour simuler des visites sur diverses URLs (/hello, /notFound, et /30), et on verra ce que le profilage nous raconte :)

Les outils testés

dtrace sur SmartOS

dtrace est en théorie l’outil de choix pour NodeJS. Le problème est qu’il ne fonctionne correctement que sur Solaris. Oui, moi aussi ça me fait le même effet quand je lis « Solaris », un peu comme quand j’entends « patin à roulettes » ou « tatoo »… Joyent nous a concocté un OS fait maison basé sur Solaris, et fonctionnant sur un système de Virtual Machines assez simples à installer: on définit une « zone » qui correspond à un contexte d’exécution avec la configuration réseau associée, et ça installe la VM pré-configurée qui va bien.

SmartOS n’est donc qu’un gestionnaire de VMs pré-packagées, incluant des VMs dédiées au développement sous NodeJS. Les VMs tournent sous un dérivé de NetBSD (avec son gestionnaire de paquets pkgsrc).

Sur le papier, que du bonheur. En pratique SmartOS me pose un vrai problème: c’est du vieil Unix qui fait mal aux doigts, on est très loin des Linux Debianoides qui se configurent facilement, avec un million de tutos sur le net. Là si tu as merdé dans tes DNS tu es seul, nu, face à l’immensité de ton ignorance.

Bref, installation de VirtualBox en suivant un guide plutôt bien fait (encore plus simple: un script pour installer la VM ;)). J’ai découvert entre temps un autre guide bien plus complet qui vous décrira bien mieux la phase d’installation de la zone.

  1. Petite surprise: la zone la plus récente inclut node version… 0.6.8. Why, Joyent ? Why ?
  2. Petite galère: on se retrouve avec une VM dans une VM, donc il faut bidouiller un peu pour pouvoir se connecter directement à la deuxième VM en SSH (cf. premier guide).
  3. Truc relou: j’ai merdé ma config réseau, j’ai du tout recommencer tellement j’étais incapable de trouver où configurer ça… OK.
  4. J’ai finalement laissé tomber, entre les problèmes de mapping clavier et les difficultés d’installation du moindre paquet, ça m’a gonflé.

On peut dire que ce fut un échec, en grande partie dû à mon manque d’expérience. Je ne vais donc pas jeter la pierre sur SmartOS mais méfiez-vous si vous voulez l’utiliser ça n’est pas simple du tout, il faut un peu d’expérience. Je vais insister, et je reviendrai avec un article qui décrit mes échecs et comment je les ai dépassés. En attendant, pas de dtrace :)

Les pistes alternatives: utiliser dtrace, ltrace, ou strace sous Linux. Je n’ai pas testé car il est dit partout que ça n’est pas une solution fiable.

node-profiler et le profileur V8

NodeJS permet de passer au binaire des options à destination de V8 (voir la liste avec node --v8-options), dont celles qui nous intéressent --prof et --prof_auto. En exécutant notre programme avec node --prof --prof_auto on aura un fichier v8.log généré à côté, exploitable avec des parseurs dont linux-tick-processor fourni dans les dépendances de node. En pratique ce programme a échoué chez moi, mais un petit npm install profiler fournit l’exécutable nprof qui lui fonctionne parfaitement :)

ab -n 1000 -c 10 http://localhost:33331/hello > ab-hello1.txt & \
ab -n 100 -c 2 http://localhost:33331/30 > ab-fibo1.txt & \
ab -n 1000 -c 10 http://localhost:33331/notFound > ab-notFound1.txt &

On obtient un fichier v8.log de 4.2 Mo, et nprof nous sort une analyse, dont ce qui nous intéresse est la partie « Bottom up profile »:

 [Bottom up (heavy) profile]:
  Note: percentage shows a share of a particular caller in the total
  amount of its parent calls.
  Callers occupying less than 2.0% are not shown.

   ticks parent  name
   4111   62.2%  /lib/x86_64-linux-gnu/libc-2.15.so

   1175   17.8%  LazyCompile: *fibo_sync /home/nchambrier/Bureau/http1.js:18
   1175  100.0%    LazyCompile: *fibo_sync /home/nchambrier/Bureau/http1.js:18
   1175  100.0%      LazyCompile: *fibo_sync /home/nchambrier/Bureau/http1.js:18
   1175  100.0%        LazyCompile: *fibo_sync /home/nchambrier/Bureau/http1.js:18
   1175  100.0%          LazyCompile: *fibo_sync /home/nchambrier/Bureau/http1.js:18
   1175  100.0%            LazyCompile: *fibo_sync /home/nchambrier/Bureau/http1.js:18

    889   13.5%  Stub: CallFunctionStub_Args1_Implicit
    888   99.9%    LazyCompile: *fibo_sync /home/nchambrier/Bureau/http1.js:18
    888  100.0%      LazyCompile: *fibo_sync /home/nchambrier/Bureau/http1.js:18
    888  100.0%        LazyCompile: *fibo_sync /home/nchambrier/Bureau/http1.js:18
    888  100.0%          LazyCompile: *fibo_sync /home/nchambrier/Bureau/http1.js:18
    888  100.0%            LazyCompile: *fibo_sync /home/nchambrier/Bureau/http1.js:18

    332    5.0%  /usr/local/bin/node
    138   41.6%    LazyCompile: *fibo_sync /home/nchambrier/Bureau/http1.js:18
    138  100.0%      LazyCompile: *fibo_sync /home/nchambrier/Bureau/http1.js:18
    138  100.0%        LazyCompile: *fibo_sync /home/nchambrier/Bureau/http1.js:18
    138  100.0%          LazyCompile: *fibo_sync /home/nchambrier/Bureau/http1.js:18
    138  100.0%            LazyCompile: *fibo_sync /home/nchambrier/Bureau/http1.js:18
     29    8.7%    LazyCompile: *Socket._destroy net.js:294
     28   96.6%      LazyCompile: *afterWrite net.js:494
      1    3.4%      Function: ~afterWrite net.js:494
     22    6.6%    LazyCompile: *NativeModule.compile node.js:537
     22  100.0%      Function: ~NativeModule.require node.js:492
      6   27.3%        Function: ~Module._findPath module.js:158
      6  100.0%          Function: ~Module._resolveFilename module.js:322
      6  100.0%            Function: ~Module._load module.js:274
      5   22.7%        Function: ~Module._load module.js:274
      5  100.0%          Function: ~Module.require module.js:358
      5  100.0%            Function: ~require module.js:374
…

Pour exploiter ça je vous conseiller de chercher les ressources sur l’optimisation de V8, notamment les très bon slides de la présentation «V8 Performance Tuning Tricks».

On voit que notre fonction fibo_sync apparaît plusieurs fois, avec à chaque fois de gros chiffres. Même sans rentrer dans le détails en lisant un rapport comme celui-là on comprend tout de suite qui est le potentiel goulot d’étranglement. En analysant le code et les logs d’accès on se rendra compte que seule l’URL /30 appelle fibo_sync(), et que cette URL n’est appelée que 100 fois sur 2100 requêtes. Elle apparaît sur 40% des snapshots en n’étant appelée que par 5% des visites. On voit comment le profilage par échantillonnage n’est réellement utile qu’avec d’autres éléments d’informations par ailleurs, mais on arrive à des conclusions tout de même très précises!

En faisant le même travail sur la version blindée de process.nextTick(), on obtient ça:

   ticks parent  name
  134536   93.6%  /lib/x86_64-linux-gnu/libc-2.15.so

   7021    4.9%  /usr/local/bin/node
   2689   38.3%    LazyCompile: bind native v8natives.js:1456
   1972   73.3%      LazyCompile: *fibo_async /home/nchambrier/Bureau/http2.js:18
   1971   99.9%        Function: ~d native v8natives.js:1480
   1965   99.7%          LazyCompile: *startup.processNextTick.process._tickCallback node.js:185
    425   15.8%      Function: ~next1 /home/nchambrier/Bureau/http2.js:25
    425  100.0%        Function: ~d native v8natives.js:1480
    425  100.0%          LazyCompile: *startup.processNextTick.process._tickCallback node.js:185
    288   10.7%      Function: ~next2 /home/nchambrier/Bureau/http2.js:32
    288  100.0%        Function: ~d native v8natives.js:1480
    288  100.0%          LazyCompile: *startup.processNextTick.process._tickCallback node.js:185
   1246   17.7%    Function: ~d native v8natives.js:1480
   1241   99.6%      LazyCompile: *startup.processNextTick.process._tickCallback node.js:185
    441    6.3%    LazyCompile: *startup.processNextTick.process.nextTick node.js:197
    300   68.0%      LazyCompile: *fibo_async /home/nchambrier/Bureau/http2.js:18
    300  100.0%        Function: ~d native v8natives.js:1480
    299   99.7%          LazyCompile: *startup.processNextTick.process._tickCallback node.js:185
     85   19.3%      Function: ~next1 /home/nchambrier/Bureau/http2.js:25
     85  100.0%        Function: ~d native v8natives.js:1480
     85  100.0%          LazyCompile: *startup.processNextTick.process._tickCallback node.js:185
     55   12.5%      Function: ~next2 /home/nchambrier/Bureau/http2.js:32
     55  100.0%        Function: ~d native v8natives.js:1480
     55  100.0%          LazyCompile: *startup.processNextTick.process._tickCallback node.js:185

Même genre de chiffres, de façon surprenante même un peu plus simple à lire. Je me dis que c’est simplement puisqu’on a en fait cassé la récursivité. Les mêmes conclusions d’optimisation s’imposent.

Pour les curieux je tournais à 40 req/s avec la première implémentation, et 10 req/s avec la deuxième (qui d’ailleurs a régulièrement planté sur de trop grosses valeurs). Ça rejoint ce que j’expliquais dans un précédent article: pas la peine de croire qu’on va gagner quoi que ce soit à faire du « faux parallèle » quand on a des calculs bloquants. Pour ça il n’y a que les threads qui puissent aider.

nodetime

Nodetime est un module mais surtout un service associé: on active le module dans son application, et il nous fournit une URL où consulter les statistiques. Cet outil n’est utile que pour profiler un serveur HTTP(S), dans tous les autres cas il vous sera inutile.

On ajoute donc simplement require('nodetime').profile() en tête de notre programme:

On effectue le même test avec ab et on se rend tout simplement à l’URL indiquée.

On va trouver des éléments intéressants et faciles à interpréter:

  • Dans la partie « Transactions » on va pouvoir suivre en temps réel les requêtes, la valeur qui nous intéresse ici est « CPU Time » pour voir quelles requêtes prennent du temps. On peut alors voir les entêtes envoyées pour avoir le contexte, cela permet de savoir rapidement où notre serveur a besoin d’optimisation. On retrouve sans surprise « /30 » dans notre exemple.
  • Dans la partie « Tools », on a le « CPU Profiler » qui va nous permettre de récupérer un échantillon sur une période donnée. À exécuter donc au moment où on rejoue une des requêtes à optimiser, de manière à avoir les données intéressantes 😉 On retrouve la notion de « Hot Spot » qui ici semble plus facile à interpréter qu’avec la sortie de nprof, où on retrouve notre fibo_sync().La même expérience sur la seconde implémentation donne un résultat intéressant au niveau du CPU Profiler: les appels à fibo_async() n’apparaissent pas tout de suite car ils sont camouflés derrière les appels à process.nextTick(). On a là le résultat typique d’une tentative de parallélisation ratée 😛

    Un outil extrêmement intéressant, très simple à utiliser et fournit des informations utiles. Le côté SaaS peut être un avantage comme un inconvénient selon le contexte… On pourra regarder du côté du projet look, basé sur nodetime mais avec serveur local.

    valgrind

    Valgrind est un outil de débuggage générique. Son outil de travail par défaut (memcheck) permet de détecter les fuites mémoires, mais c’est un autre sujet 😉 En l’occurrence on utilisera l’outil intégré callgrind qui génèrera des fichiers cachegrind, dont l’avantage est qu’il existe pas mal d’outils pour traiter ces fichiers, notamment le populaire kcachegrind.

    Un petit apt-get install valgrind plus tard, on peut lancer valgrind --tool=callgrind --callgrind-out-file=fichier-callgrind.out node server.js et lancer le bench. C’est affreusement lent (au moins 10 fois plus lent qu’en temps normal), donc j’ai largement réduit le nombre de requêtes envoyés par ab.

    Le fichier de sortie ouvert dans kcachegrind donne ceci:

    Franchement, je ne sais toujours pas comment l’utiliser car on n’y retrouve nulle part les références à nos noms de fonctions…

    Là encore, si vous parvenez à de meilleurs résultats, je suis preneur 😉

    webkit-devtools-agent

    Le module webkit-devtools-agent permet d’activer le profileur V8 et d’utiliser les outils de débuggage de Webkit pour débugger son application. Sur le même principe que nodetime il suffit d’un npm install webkit-devtools-agent et d’ajouter en tête de son application require('webkit-devtools-agent'). Il suffit d’envoyer le code SIGUSR2 pour activer l’agent, et de le renvoyer pour le désactiver.

    L’interface de débuggage se trouve à l’URL indiquée dans le README (la page ne fournit que l’interface, qui va directement chercher les données sur votre machine, il n’y a pas de plateforme de récolte des données ici contrairement à nodetime), dans mon cas (node 0.6) http://c4milo.github.com/node-webkit-agent/19.0.1084.46/inspector.html?host=localhost:1337&page=0. Ça se présente comme la barre Chrome. L’onglet qui nous intéresse est évidemment « Profiles ».

    On active la collecte d’informations CPU, on lance notre bench et voilà ce qu’on obtient:

    On voit bien l’impact comparé de « respond() » et de « fibo_sync()« , on en tire rapidement les mêmes conclusions que précédemment.

    En faisant le même expérience sur l’implémentation asynchrone on obtient un résultat tout aussi clair et exploitable:

    Conclusion

    L’expérience n’est pas une complète réussite, néanmoins je ressors de là avec de vrais outils opérationnels, donc tout n’est pas si noir 😉 Ma prochaine étape sera de dompter cette foutue VM SmartOS pour avoir un environnement de débuggage optimal. En attendant j’ai trouvé mon bonheur avec le profileur V8, et je suis très tenté d’utiliser nodetime sur des applications en prod pour récolter des statistiques très complètes sur une période donnée: le croisement des logs HTTP et du profiling CPU permettant d’avoir des infos efficacement.

    Voici un tableau récapitulatif totalement subjectif:

    Outil Simplicité d’usage Profiling post-mortem Profiling en temps réel Requiert un service tiers Commentaire
    SmartOS + dtrace Un peu farouche… Oui Oui Non, mais nécessite une VM spécifique La solution la plus complète a priori, mais la moins simple d’approche
    V8 Profiler Directement intégré Oui Oui Non Simple et efficace, ce sera ma solution de choix au quotidien
    nodetime Requiert une modification de code Pas sûr Oui Oui Le côté SaaS peut être sympa, belle UI, croisement avec les logs HTTP rendu plus simple. Mon deuxième choix.
    valgrind Simple mais résultats peu exploitables Oui Pas sûr (*) Non
    webkit-devtools-agent Requiert une modification du code Non Oui L’UI est hébergée, mais les données transitent localement Jolie UI

    (*) peut-être voir du côté de callgrind_control.

    L’intégration du profileur V8 permet d’avoir un outil efficace à portée de main, mais je garde un œil sur nodetime pour son approche résolument différente et cependant utile. J’espère pouvoir rapidement réviser mon jugement sur le couple SmartOS/dtrace.

    Si vous avez d’autres outils à me conseiller, ou des ressources permettant d’améliorer ma prise en main de SmartOS, valgrind, ou autre, je suis preneur!

    Avec tout ça, j’ai même pas fait le profiling de mon application, j’y retourne 😉

Une réflexion au sujet de « Profiler son application NodeJS »

  1. larafale

    merci top, ca donne un super point de départ pour se lancer dans le profiling.
    très important pour des app à fort traffic.

    perso smartOS une VM ds une VM, tu sais d’avance que tu va galèrer :)
    par contre nodetime à l’air pas mal

    a+

    Répondre

Laisser un commentaire