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
- Le profilage statistique
- Le cas pratique
- Les outils testés
- Conclusion
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 
). 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.
- Petite surprise: la zone la plus récente inclut node version… 0.6.8. Why, Joyent ? Why ?
- 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).
- Truc relou: j’ai merdé ma config réseau, j’ai du tout recommencer tellement j’étais incapable de trouver où configurer ça… OK.
- 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 notrefibo_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é surnodetimemais avec serveur local.valgrindValgrind 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é callgrindqui 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 valgrindplus tard, on peut lancervalgrind --tool=callgrind --callgrind-out-file=fichier-callgrind.out node server.jset 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 parab.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-agentLe module
webkit-devtools-agentpermet 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 quenodetimeil suffit d’unnpm install webkit-devtools-agentet d’ajouter en tête de son applicationrequire('webkit-devtools-agent'). Il suffit d’envoyer le codeSIGUSR2pour 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
nodetimepour 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
Comments:1
Laisser un commentaire