URL: https://linuxfr.org/news/hotspot-a-la-recherche-du-point-chaud Title: Hotspot, à la recherche du point chaud… Authors: Pinaraf Nils Ratusznik, palm123, Julien Jorge et Ysabeau Date: 2021-04-11T15:40:02+02:00 License: CC By-SA Tags: performance et linux Score: 4 Depuis maintenant quelques semaines, j’ai repris les contributions au projet Calligra, et plus particulièrement au traitement de texte (cf [ce journal](https://linuxfr.org/users/pied/journaux/723-5736-5696-un-mois-de-travail-de-resurrection-d-un-projet-libre) pour plus d’informations). Du coup, quand sur la liste de courriel des développeurs un [comparatif](https://mail.kde.org/pipermail/calligra-devel/2021-March/017938.html) a été envoyé, comparant LibreOffice et Calligra sur le temps de chargement d’un document volumineux (800+ pages, table des matières de 60+ pages), et révélant un sévère désavantage pour Calligra, mon sang ne fit qu’un tour : un facteur 4 dans le temps de chargement n’est pas acceptable, même s’il s’explique par l’absence de travail d’optimisation sur ce point… Partons donc à la recherche de ces lenteurs, et profitons-en pour parler des méthodes d’analyse des performances d’un programme sous Linux ! ---- [Calligra](https://calligra.org/) [Hotspot (Github)](https://github.com/KDAB/hotspot/) [Linux perf](https://perf.wiki.kernel.org/index.php/Main_Page) ---- 1) dans des temps anciens, callgrind… ===================================== Valgrind est un outil bien connu des développeurs C/C++ notamment. Il est connu comme étant un excellent outil pour détecter et analyser les problèmes mémoire, qu’il s’agisse de fuites ou d’utilisation de pointeurs libérés… Mais c’est une vraie collection d’outils, avec également celui qui fut un grand allié dans la recherche des problèmes de performance, callgrind. Callgrind fonctionne en remplaçant le programme de chargement du binaire par le sien, et en faisant une analyse dynamique du code au fur et à mesure de son exécution. Cette analyse est complète (il ne s’agit pas d’instantanés à une fréquence donnée) mais a un coût colossal : un programme dans callgrind peut facilement être dix fois plus lent qu’en dehors de callgrind. Sur un programme complexe, on procède souvent à une analyse réduite avec un déclenchement retardé de callgrind, puis en l’interrompant quand l’événement que l’on souhaite analyser est passé. L’illustration en est donnée sur [cet article d’analyse de plasma avec callgrind](https://web.archive.org/web/20111105130616/http://blog.bepointbe.be/index.php/2008/10/19/30-a-bit-of-plasma-profiling). Heureusement, ce temps est désormais révolu et d’autres outils sont disponibles maintenant, bien plus flexibles. Celui que je vais utiliser est désormais un indispensable dans ma boite à outil, qu’il s’agisse d’administration système, de travail de DBA ou de développement : `perf`. 2) Performance Counters for Linux, perf, la révolution… ======================================================= Bon la révolution ne date pas d’hier (2009 dans le noyau, 2010 dans RHEL, 2011 dans Debian Squeeze…), mais finalement on en a peu parlé sur DLFP, et ce n’est donc pas si connu que ça… Ou l’inverse, je ne sais plus… `perf` utilise les compteurs matériel, des points de traçage dans le noyau ou dans les applications afin de collecter des événements. Qu’est-ce qu’un événement, me direz-vous ? Je suis heureux que vous me posiez cette question : la commande `perf list` en liste plus de 300 chez moi… Ils se répartissent en deux catégories selon l’origine, logicielle ou matérielle. Par exemple chaque changement de tâche par l’ordonnanceur du noyau va être un événement logiciel. Les événements matériels correspondent quant à eux aux données de la PMU (Performance Monitoring Unit), une partie du processeur qui va surveiller des événements au niveau micro-architectural comme le nombre de cycles écoulés, les succès/échecs sur le cache… Bien évidemment, on ne peut pas enregistrer chaque occurrence de ces événements : à chaque seconde, des milliards de cycles s’écoulent, et traiter ces événements déclencherait à nouveau un nombre conséquent d’événements… Le processeur maintient donc des compteurs d’événements, que le noyau va consulter. `perf` est donc la face visible de tout ce travail, et permet donc pendant une période et à une fréquence donnée d’enregistrer et visualiser le nombre d’occurrences de ces événements. 2.a) Petit exemple ------------------ Prenons un cas simple, `echo 'bonjour monde'` : ``` % perf stat /bin/echo 'bonjour monde' bonjour monde Performance counter stats for '/bin/echo bonjour monde': 0.42 msec task-clock:u # 0.556 CPUs utilized 0 context-switches:u # 0.000 K/sec 0 cpu-migrations:u # 0.000 K/sec 62 page-faults:u # 0.146 M/sec 205,471 cycles:u # 0.485 GHz 14,061 stalled-cycles-frontend:u # 6.84% frontend cycles idle 45,629 stalled-cycles-backend:u # 22.21% backend cycles idle 219,967 instructions:u # 1.07 insn per cycle # 0.21 stalled cycles per insn 49,000 branches:u # 115.556 M/sec branch-misses:u (0.00%) 0.000763131 seconds time elapsed 0.000819000 seconds user 0.000000000 seconds sys ``` L’exécution de cette commande simple a duré 0,76ms, 205 000 cycles processeurs, 220 000 instructions, avec une consommation de 0,42ms de CPU. Pour comparaison, avec `sleep 1` : ``` % perf stat sleep 1 Performance counter stats for 'sleep 1': 0.45 msec task-clock:u # 0.000 CPUs utilized 0 context-switches:u # 0.000 K/sec 0 cpu-migrations:u # 0.000 K/sec 62 page-faults:u # 0.137 M/sec 249,795 cycles:u # 0.554 GHz 21,583 stalled-cycles-frontend:u # 8.64% frontend cycles idle 60,183 stalled-cycles-backend:u # 24.09% backend cycles idle 221,601 instructions:u # 0.89 insn per cycle # 0.27 stalled cycles per insn 49,186 branches:u # 109.046 M/sec branch-misses:u (0.00%) 1.001224745 seconds time elapsed 0.000899000 seconds user 0.000000000 seconds sys ``` On note que le task-clock reste très faible puisqu’il s’agit du temps processeur consommé, et sleep ne fait pas une attente active où il consommerait inutilement du processeur. 2.b) perf top pour voir ce que fait notre système ------------------------------------------------- perf top permet d’avoir une vue instantanée de tout le système, noyau inclus. Lors de cette capture, un `btrfs scrub` est en cours sur deux disques en LUKS. ![Perf top avec un btrfs scrub en arrière-plan](https://rock.pinaraf.info/~pinaraf/illustrations-dlfp/perf-top-scrub.png) Vous notez en haut de l’interface que l’événement capturé est 'cycles' (le nombre de cycles processeur consommés), à une fréquence de 4 kHz (4 000 captures par seconde, pour les moins scientifiques d’entre nous). Cela montre le fonctionnement de perf qui réalise un échantillonnage du système. Dans cette interface, on peut également aller dans chaque fonction et annoter les fonctions pour voir exactement où le CPU est consommé. Quand on ne dispose pas des symboles de debug (mon principal reproche contre Archlinux), le code assembleur sera affiché. ![Détail du temps passé sur une fonction dans perf top](https://rock.pinaraf.info/~pinaraf/illustrations-dlfp/perf-top-annotate.png) Cette commande est utilisable également sur un serveur en production, et peut donc aider dans des cas sensibles d’analyse de performances : elle n’a pas d’impact sur le système quand il tourne, et permet de creuser très facilement sur les fonctions les plus gourmandes en CPU, qu’il s’agisse de fonctions dans l’espace utilisateur ou dans l’espace noyau. Grâce à cet outil, un collègue et moi-même avons su identifier (puis corriger avec les outils présentés ensuite) un problème de performance sur PostgreSQL où la réplication logique provoquait une forte consommation de CPU en système. 2.c) perf record pour analyser un programme ------------------------------------------- La commande `perf record` est, dans le cas qui nous intéresse ici, la plus utile. Elle permet, pour un ensemble de processus donnés (ou l’ensemble du système) d’enregistrer un fichier `perf.data` qui va contenir un ensemble d’événements. Nous pourrons ensuite utiliser des outils comme `perf report` pour disposer de la même interface que `perf top`, mais sur un état figé. Quand on dispose d’un élément reproductible (ici, ouvrir et afficher le fichier OpenDocument-v1.2-part1.odt), on peut facilement modifier l’application pour comparer l’évolution. Un paramètre assez important à `perf record` est `--call-graph` qui permet d’enregistrer les piles d’appel à chaque événement. Ainsi, au lieu de voir que l’on a passé 50 % du temps dans une fonction foo(), on peut découvrir qu’en fait on a passé 45 % du temps dans un appel de foo() par bar(), et 5% du temps dans des appels divers à foo(). Plusieurs valeurs peuvent être passées à --call-graph, pour spécifier la méthode de capture des piles d’appel, avec un choix entre `fp` (utilisation du 'frame pointer' qui doit être mis par le compilateur), `dwarf` (utilisation des données de debug du programme) et `lbr` (utilisation des registres LBR, disponibles uniquement sur les processeurs Intel récents). Dans mon cas, j’utilise dwarf qui m’a donné les meilleurs résultats. Un autre paramètre optionnel est `-F` pour spécifier la fréquence d’échantillonnage. Sur des périodes de captures courtes, ce paramètre peut être utile pour obtenir des traces plus utilisables. Lançons ça sur Calligra Words : ``` % perf record --call-graph dwarf ./words/app/calligrawords ../OpenDocument-v1.2-part1.odt [… sortie diverse de debug de différents composants de calligra …] [ perf record: Woken up 2749 times to write data ] Warning: Processed 93565 events and lost 21 chunks! Check IO/CPU overload! [ perf record: Captured and wrote 691.125 MB perf.data (85798 samples) ] ``` 691 MB, c’est costaud. D’ailleurs, un certain nombre d’événements n’ont pas pu être capturés. Ajouter les paramètres `--aio -z` règlent ce souci en compressant la sortie et en faisant des IOs asynchrones. Avec `perf report`, on peut explorer l’enregistrement, ce qui donne une interface (et des fonctionnalités) proches de `perf top` : ![Aperçu de l'enregistrement de Calligra dans perf report](https://rock.pinaraf.info/~pinaraf/illustrations-dlfp/perf-report.png) Néanmoins, sur un programme aussi complexe qu’un traitement de texte, cet affichage n’est pas le plus adapté… Heureusement… 3) hotspot, rendons ça plus visuel… =================================== KDAB est une société de service en logiciels, spécialisée sur Qt, qui contribue au libre : plusieurs de ses salariés sont d’éminents développeurs KDE, elle a envoyé de nombreux patchs sur Qt, ouvert différents outils autour de Qt… Et l’un de ses derniers nés est hotspot, je cite, « L’interface à Linux perf pour l’analyse de performance », disponible en licence GPL ou commerciale. L’outil est extrêmement simple à prendre en main : on ouvre dans l’interface le fichier `perf.data`, et après quelques secondes, l’interface (très complète) apparaît. ![Aperçu de l'enregistrement de Calligra dans hotspot](https://rock.pinaraf.info/~pinaraf/illustrations-dlfp/perf-hotspot-summary.png) La visualisation la plus intéressante est le 'Flame Graph'. Grâce à lui, on peut en quelques instants voir où le temps s’est écoulé, et donc en déduire les endroits à optimiser. ![Flame-graph de l'enregistrement de Calligra dans hotspot](https://rock.pinaraf.info/~pinaraf/illustrations-dlfp/perf-hotspot-flame-before.png) On trouve donc facilement le point chaud, il n'y a « plus qu’à » le corriger… Bon, « le plus qu’à » a pris plusieurs jours, plusieurs patchs, des versions incorrectes, différents atermoiements… Les plus curieux peuvent aller regarder sur [cette 'merge-request'](https://invent.kde.org/office/calligra/-/merge_requests/27) pour les correctifs de cette fonction, sachant que d’autres correctifs ont été intégrés entre-temps pour d’autres points 'tièdes' repérés avec hotspot également. Une fois ce point chaud corrigé, un second point chaud était assez apparent : l’ajout de texte dans un QTextDocument. L’analyse a permis de révéler un algorithme en O(n) lors de l’ajout de textes sur QTextDocument en fonction du nombre de curseurs qu’on maintient sur le document. Or, dans Calligra, chaque annotation et chaque marque-page dans le document est représenté avec un curseur, et il y en a plusieurs milliers. Là aussi, les plus curieux peuvent aller voir [le bug Qt correspondant](https://bugreports.qt.io/browse/QTBUG-92153) que j’espère corriger dans les prochains mois… Hé oui, contribuer à un logiciel peut parfois amener à en corriger beaucoup plus… Pour information, une fois les problèmes corrigés, je suis arrivé à ce niveau de performances : ![Flame-graph de l'enregistrement de Calligra dans hotspot après optimisation](https://rock.pinaraf.info/~pinaraf/illustrations-dlfp/perf-hotspot-flame-after.png) On voit que le temps requis pour ouvrir le fichier est passé de 20 secondes à 8 secondes, et hotspot va continuer de m’aider à trouver les endroits restant à optimiser. Attention tout de même : le principal inconvénient d’un tel outil est sa simplicité d’utilisation. C’est assez « enivrant » et l’on se prend vite au jeu de gratter des cycles CPU à droite et à gauche, quitte à délaisser le développement de fonctionnalités ou la correction de bugs… J’espère en tout cas que cet article vous permettra de trouver d’autres optimisations à faire sur les programmes que vous développez ou utilisez.