Graphes d’appels

Motivation

Dans la partie sur perf trace, nous avons vu que la mesure de graphes d’appels nous permet de comprendre l’origine d’une activité système. Dans le cadre de perf report, cette mesure est aussi possible, et même très utile :

  • Elle nous permet de discriminer des appels à une fonction qui surviennent pour différentes raisons. Dans notre exemple, nous pouvons ainsi savoir quelles parties du code passent le plus de temps à appeler l’allocateur mémoire, afin de prioriser les optimisations associées.
  • Elle nous permet d’acquérir une vision plus haut niveau de l’activité système de notre programme. Dans notre exemple, nous n’avons plus besoin de nous préoccuper de détails d’implémentation de l’allocateur mémoire pour effectuer notre analyse.

Cependant, il y a aussi quelques nouvelles précautions à prendre par rapport à perf trace, qui sont principalement liées au fait que…

  • perf record est généralement utilisée pour échantillonner à haute fréquence (ex: par défaut, on échantillonne le pointeur d’instruction à plusieurs kHz), là où perf trace est principalement pensée pour suivre des appels système relativement peu fréquents.
  • perf record produit un fichier perf.data en sortie au lieu de traiter les données à la volée, ce qui peut créer un goulot d’étranglement en termes de bande passante de stockage ou bien perturber l’exécution d’un benchmark sensible à la performance de stockage.

Pour éviter ces problèmes, on voudra généralement spécifier manuellement une fréquence d’échantillonnage peu élevée et parfois écrire les données de sortie en RAM.

Exemple DWARF

Voici un premier exemple de cycle perf record/report qui prend ces deux précautions, en utilisant des graphes d’appels basées sur les informations de déboguage (qui constituent, pour rappel, le meilleur choix par défaut quand on est indécis) :

srun --pty \
    perf record -F 1000 --call-graph=dwarf -o /dev/shm/${USER}/perf.data \
    ./TPhysics.bin 500 100 \
&& mv /dev/shm/${USER}/perf.data . \
&& perf report

Rapport avec graphes d’appels

On peut constater la présence de nombreuses nouveautés dans l’affichage :

  • L’ancienne colonne Overhead est renommée en Self et placée en 2e position.
  • Il y a une nouvelle colonne Children, qui représente une estimation du temps passé dans une fonction X ainsi que dans l’ensemble des fonctions directement ou indirectement appelées par X. Cette colonne est la nouvelle clé de tri.
  • Au niveau des symboles, le code de discrimination entre fonctions utilisateur et noyau cette version de perf semble un peu bogué…
  • perf est parfois (hélas pas à tous les coups) en mesure d’estimer le temps CPU consommé par les fonctions inlinées, ce qui est utile car elles sont souvent critiques pour les performances.

Une lettre + a également fait son apparition sur la gauche de l’affichage. Ce signe nous indique qu’en mettant en surbrillance une fonction et en appuyant sur la touche Entrée, on peut afficher la répartition du temps CPU entre les fonctions appelées, et ce récursivement si on le souhaite :

Répartition du temps CPU dans main

Limites du DWARF

Voilà pour les bonnes nouvelles. Maintenant, la grosse mauvaise nouvelle. Il ne vous aura pas échappé que seulement 79% des piles d’appels ont correctement été reconstruites jusqu’à la fonction main. Ceci est une occasion de plus de répéter un point central dans l’interprétation de toutes les mesures perf basées sur l’analyse des informations de déboguage :

Les analyses basées sur les informations de déboguage sont loin d’être infaillibles, et ce pour toutes sortes de raisons difficiles à analyser pour le non-expert : bogues du compilateur, de binutils, de perf, ou taille d’échantillon de pile insuffisante.

En pratique, pour les 21% de piles d’appels restantes, la remontée de la pile d’appels a bien fonctionné jusqu’à un certain point, puis une erreur s’est produite en cours de route et perf a atterri à une adresse d’instruction insensée avant d’abandonner, comme on peut s’en convaincre avec une analyse à gros grain de ces échantillons pathologiques basée sur le binaire source :

perf report --call-graph=comm,dso

Vue en DSO du graphe d’appels

La conséquence de cela, c’est que les pourcentages Children obtenus sur un graphe d’appels DWARF ne sont pas fiables à 100%. Au mieux, les échantillons mal reconstruits sont équirépartis dans le programme et on a “juste” besoin de normaliser les valeurs obtenues dans le graphe d’appels qui commence à main par 1/79% = 1.26. Au pire on a un problème qui se produit toujours au même endroit du code, et cela créera un biais systématique d’au plus 21% dans les mesures.

Sans information complémentaire, une façon prudente d’interpréter les données est de conclure quel les pourcentages “Children” que l’on obtiendrait avec une mesure parfaite sont compris entre la valeur mesurée X et X+(100-M) où M est le pourcentage “Children” mesuré pour la fonction main (qui devrait être ~100% pour tout programme dont le temps d’exécution n’est pas négligeable, en l’absence d’erreur de reconstruction des piles d’appels).

Pour faire mieux, il faut avoir sous la main une deuxième technique de profilage qui n’est pas sujette aux mêmes biais que les graphes d’appels DWARF afin d’évaluer le niveau de biais lié aux piles d’appels tronquées. Cela peut être un profilage manuel au sein de l’application, mais dans le cadre de perf report, on peut aussi parfois utiliser les graphes d’appels LBR.

Exemple LBR

Au niveau de perf record, on utilise ce style de graphe d’appels avec l’option --call-graph=lbr :

srun --pty \
    perf record --call-graph=lbr \
    ./TPhysics.bin 500 100 \
&& perf report

Rapport avec graphes d’appels LBR

Sur ce programme qui reste relativement simple, et donc sous la limite des 32 appels de fonction imbriqués supportés par le LBR de notre CPU, le graphe d’appels par LBR produit de bons résultats. On peut observer les différences suivantes avec le graphe d’appels par information de déboguage :

  • Presque toutes les piles d’appels sont ici reconstruites jusqu’à main.
  • La discrimination entre code applicatif et code du noyau Linux fonctionne à tous les coups.
  • On n’a plus de visibilité sur les fonctions inlinées.
  • L’information LBR est beaucoup plus légère que les copies de piles requises pour l’analyse DWARF, donc on n’a plus besoin d’imposer une limite de fréquence d’échantillonnage ou d’émettre le fichier de sortie sur /dev/shm. L’analyse par perf report est aussi plus rapide.

Au niveau du résultat, on peut comparer le premier niveau de hiérarchie sous main pour les deux techniques, en descendant jusqu’à la première fonction non inlinée dans le cas du graphe d’appels DWARF pour faciliter la comparaison :

Comparaison DWARF/LBR

Une petite règle de trois permet de se convaincre qu’il n’y a pas de biais systématique majeur ici : en renormalisant les pourcentages “Children” du graphe d’appels DWARF par 1/0.7978 (l’inverse du pourcentage d’échantillons correctement reconstruit jusqu’à main), on trouve…

  • 40.6% pour TProton::interaction
  • 19.3% pour TNucleon::interaction
  • 14.1% pour TChargedParticle::interaction
  • 8.5% pour TVector::vectorOp
  • 1.8% pour std::vector<double>::operator=

…ce qui est en plutôt bon accord avec le profil mesuré par la méthode LBR. On notera cependant quelques différences. Par exemple l’approche DWARF attribue le coût de déallocation des std::vector à la fonction _int_free de la glibc alors que l’approche LBR l’attribue à l’opérateur delete de la libstdc++, et il semblerait que l’approche DWARF ne parvienne pas à reconstruire les piles d’appels passant par la méthode virtuelle TChargedParticle::interaction.

Exercice : Répétez cette analyse avec les enfants de la fonction TParticle::reidInteraction.

Notez la présence d’une indication _start dans la visualisation de perf report, qui représente la pile d’appels au-dessus de la fonction courante (de _start jusqu’à la fonction active).

Contourner la limite de taille du LBR

Sur des programmes plus complexes, l’approche LBR n’est souvent pas directement applicable, car les piles d’appels sont profondes et dépassent largement la limite de 32 appels de fonction du matériel. C’est particulièrement vrai quand on profile un framework scripté avec du Python, car l’implémentation de l’interpréteur CPython utilise beaucoup d’appels récursifs.

Dans ce genre de cas, on peut demander à perf report de tenter de reconstruire les piles d’appels tronquées via une technique astucieuse, le LBR-stitching. L’idée est la suivante : considérons un CPU avec une capacité LBR de 4 appels et supposons que l’on ait un programme effectuant la série d’appels imbriqués suivante :

  • A1 appelle A2…
    • …qui appelle A3
      • …qui appelle A4
        • …qui appelle A5
          • …qui appelle A6

En supposant qu’un temps CPU significatif soit écoulé dans toutes les fonctions, perf observera dans ses échantillons les piles d’appels suivantes:

  • A1
  • A1 → A2
  • A1 → A2 → A3
  • A1 → A2 → A3 → A4
  • A2 → A3 → A4 → A5 (tronqué par le LBR)
  • A3 → A4 → A5 → A6 (tronqué par le LBR)

En corrélant les piles d’appels observées dans différents échantillons, perf pourra alors reconstruire les piles d’appels tronquées en déduisant que A2 a probablement été appelée par A1 et A3 a probablement été appelée par A2.

L’opération est moins hasardeuse que cette description simplifiée ne pourrait le laisser paraître, car perf n’a pas seulement accès au nom de la fonction appelante, mais plus précisément à l’adresse de l’instruction CALL associée. Mais cela reste un post-traitement dont la fiabilité n’est pas parfaite :

  • En cas d’appel à des méthodes virtuelles dans du code orienté objet, une même instruction CALL peut appeler plusieurs fonctions différentes.
  • Si beaucoup de fonctions ne font rien d’autre qu’appeler d’autres fonctions (cas de codes appliquant les bonnes pratiques d’ingénierie logicielle de façon un peu trop orthodoxe), perf aura peu d’échantillons à ces endroits, ce qui limitera l’applicabilité du stitching.
  • Plus la fréquence d’échantillonnage est faible, moins cette approche fonctionne.
  • Ce post-traitement est plus vulnérable que l’approche LBR pure au code “pathologique” (ex: lancement et capture d’exceptions).

On peut activer le stitching en passant l’option --stitch-lbr à perf report. Et quand cela ne fonctionne pas, une alternative courante pour valider les résultats des graphes d’appels DWARF est de profiler manuellement son code, par exemple en minutant et affichant le temps écoulé pendant l’exécution d’étapes de traitement de haut niveau (idéalement au moins 100ms).

Options d’affichage du graphe d’appels

perf report dispose de plusieurs options pour configurer l’affichage des graphes d’appels. On peut notamment mentionner…

  • L’option --call-graph qui se compose de plusieurs sous-options séparées par des virgules (--call-graph=x,y,z,...). Les quatre premières sont les plus importantes :
    1. La sous-option print_type définit le comportement global quand on appuie sur Entrée après avoir mis une fonction en surbrillance. Les choix les plus utiles sont :
      • fractal : Les pourcentages de temps CPU ne sont plus absolus, mais relatifs à la fonction choisie. Soyez prudent avec ce mode, il est facile de s’y laisser piéger par un gros pourcentage relatif qui correspond en fait à un faible pourcentage absolu (qui peut ne même pas être statistiquement significatif).
      • flat : La vue n’est plus hiérarchique et on a directement une liste de toutes les piles d’appels associées à la fonction sélectionnée. Ce mode est utile pour des programmes avec des piles d’appels très profondes.
      • graph : Mode par défaut (vue hiérarchique avec des pourcentages absolus), utile quand on veut configurer les autres sous-options.
    2. La sous-option threshold, définit en dessous de quel pourcentage de temps CPU une fonction sera supprimée de l’affichage (0.5% par défaut). Cela permet d’obtenir un affichage plus ou moins détaillé.
    3. La sous-option print_limit n’est considérée qu’en mode --stdio et limite le nombre de piles d’appels enfant affichées par parent (0 = illimité est le choix par défaut)
    4. La sous-option order permet de basculer entre un affichage basé sur les enfants et un affichage basé sur les parents :
      • Le mode par défaut est caller, où l’on affiche les fonctions appelées par la fonction sélectionnée (fonctions enfants, caller-based call graph).
      • En mode callee, perf affiche quelles fonctions font le plus souvent appel à la fonction sélectionnée (fonctions parents, callee-based call graph). Ce mode est utile quand on veut savoir qui fait le plus souvent appel à une fonction utilitaire. Il est aussi plus proche du fonctionnement interne de perf report (partir d’un échantillon CPU et remonter la pile d’appels), donc utile pour déboguer.
  • L’option --percent-limit a un effet analogue à la sous-option threshold de --call-graph, mais s’applique aux entrées d’histogramme (la liste affichée lors de l’ouverture de perf report), alors que threshold s’applique aux entrées parent/enfant affichées quand on parcourt la hiérarchie des appels avec la touche Entrée.
  • L’option --max-stack permet de contrôler la limite de taille de pile d’appels après laquelle perf report abandonnera l’idée de remonter jusqu’au point d’entrée (127 par défaut).

Exercice : Affichez quelles parties du code font le plus appel à _int_malloc, free et __dynamic_cast, et dans quelles proportions.

Liste des binaires utilisées

Quand on utilise des graphes d’appels basés sur les informations de déboguage DWARF (ce qu’on est souvent amené à faire sur les gros programmes), on est fréquemment confronté au besoin d’installer des paquets de déboguage, et donc de savoir quels paquets il faut installer.

Dans cette optique, la commande perf buildid-list peut être utilisée pour savoir quels binaires ont été utilisés lors de l’exécution d’un programme et quels sont les build-id associés :

perf buildid-list

Sortie de perf buildid-list

Le build-id est une somme de contrôle d’un binaire qui permet de différencier différents binaires qui portent le même nom mais ne correspondent pas exactement à la même version du code source ou n’ont pas été compilés avec les mêmes options. Le gestionnaire de paquets de certaines distributions Linux, dont openSUSE, peut installer des symboles de déboguage sur la base d’un build-id sans avoir besoin de chercher le nom et la version du paquet associé.