URL: https://linuxfr.org/news/hotspot-a-la-recherche-du-point-chaud Title: Hotspot, Ă  la recherche du point chaud... Authors: Pinaraf Nils Ratusznik, Ysabeau đŸ§¶, palm123 et Julien Jorge Date: 2021ćčŽ04月11æ—„T15:40:02+02:00 License: CC By-SA Tags: performance, linux, libreoffice, debian, postgresql, optimisation et calligra Score: 142 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.

AltStyle ă«ă‚ˆăŁăŠć€‰æ›ă•ă‚ŒăŸăƒšăƒŒă‚ž (->ă‚ȘăƒȘă‚žăƒŠăƒ«) /