Greboca  

DLFP - Dépêches  -  Hotspot, à la recherche du point chaud…

 -  Avril 2021 - 

Depuis maintenant quelques semaines, j’ai repris les contributions au projet Calligra, et plus particulièrement au traitement de texte (cf ce journal pour plus d’informations). Du coup, quand sur la liste de courriel des développeurs un comparatif 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 !

Sommaire

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.

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

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

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

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

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

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' 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 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

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.

Commentaires : voir le flux Atom ouvrir dans le navigateur

par Pinaraf, Nils Ratusznik, palm123, Julien Jorge, Ysabeau

DLFP - Dépêches

LinuxFr.org

Retour d’expérience sur l’utilisation de GrapheneOS (ROM Android libre)

 -  18 mars - 

Suite à la dépêche Comparatif : GrapheneOS vs LineageOS, je souhaitais faire part d’un retour d’expérience sur l’utilisation de GrapheneOS sur un (...)


Ubix Linux, le datalab de poche

 -  16 mars - 

Ubix Linux est une distribution Linux libre et open-source dérivée de Debian.Le nom « Ubix » est la forme contractée de « Ubics », acronyme issu de (...)


Open Food Facts : récit d’un contributeur

 -  15 mars - 

Récit de mon aventure en tant que contributeur pour le projet Open Food Facts, la base de donnée alimentaire ouverte et collaborative, où je suis (...)


Sortie de GIMP 2.99.18 (version de développement)

 -  13 mars - 

Note : cette dépêche est une traduction de l'annonce officielle de la sortie de GIMP 2.99.18 du 21 février 2024 (en anglais).Voici enfin la (...)


Des cycles, des applis et des données

 -  11 mars - 

Avec son plus d’un quart de siècle, il serait temps que LinuxFr se penche sur un sujet qui concerne la population en situation de procréer, soit (...)