Intel Processor Trace (Intel PT)

Intel Processor Trace, en abrégé Intel PT, est une fonctionnalité intégrée aux processeurs Intel depuis la génération Broadwell qui permet de suivre de façon exhaustive l’exécution d’un programme, à l’instruction assembleur près, ainsi que certains événements CPU associés (branchements, gestion d’énergie, transactions, gestion des interruptions, entrée/sortie d’une VM…).

Comme on peut l’imaginer, le volume de données produit est gigantesque même si elles sont compressées (on parle de plusieurs centaines de Mo par seconde et par coeur CPU). Le coût d’instrumentation peut être conséquent, et l’analyse peut aussi devenir coûteuse (100-1000x plus lente que l’acquisition). Ce type d’étude doit donc être réservé à des programmes dont l’exécution est très rapide, ou bien à des instants courts de l’exécution d’un programme complexe.

Dans cette partie, nous verrons comment acquérir ces données avec perf record, les afficher avec perf script, et les intégrer à une visualisation perf report.

Acquisition

Les événements Intel PT sont accessibles via l’événement intel_pt//. La syntaxe curieuse //, que nous n’avons pas abordée auparavant, permet de spécifier des paramètres pour l’acquisition, par exemple le type d’horloge utilisé. Elle est aussi utilisée quand on interroge des compteurs de performance du CPU dont le support n’a pas encore été implémenté au sein du duo perf+noyau utilisé, typiquement quand on travaille avec un noyau Linux plus ancien que son CPU.

Quoiqu’il en soit, les paramètres par défaut seront suffisant pour cette introduction. Commençons donc par faire une première analyse du code d’exemple scale.bin, configuré avec des paramètres permettant d’avoir…

  • Une boucle interne courte (64 multiplications -> 8 opérations AVX)
  • Un temps d’exécution court (quelques dizaines de millisecondes)

Pour limiter le volume de données produites, nous ne considérerons que l’activité CPU applicative en ignorant celle du noyau, ce qu’on peut faire avec l’habituel suffixe u. Et nous allons nous restreindre à une exécution séquentielle pour cet exemple afin que la sortie soit plus facile à interpréter.

cd ~/tp-perf \
&& srun make -j$(nproc) \
&& srun --pty --hint=nomultithread \
   perf record -e intel_pt//u \
   ./scale.bin 64 10000000

Affichage détaillé via perf script

En principe, on peut ensuite afficher directement la liste des instructions exécutées avec perf script --insn-trace --xed…

perf script --insn-trace --xed
Début de la sortie de perf script --insn-trace --xed

…mais avant d’arriver à l’exécution du code arithmétique qui nous intéresse, il nous faudrait d’abord passer par des millions de lignes d’assembleur exécuté par le chargeur de programme ld et l’initialisation de la bibliothèque standard. Ce n’est clairement pas viable.

A la place, nous allons commencer par la vue de plus haut niveau fournie par perf script --call-trace, qui indique notamment quelles fonctions ont été appelées, quelles fonctions ces fonctions ont appelé, et ainsi de suite. Un arbre des appels de fonction visibles du CPU (non inlinés), donc.

perf script --call-trace
Début de la sortie de perf script --call-trace

Cette sortie est encore très imposante (13201 lignes au moment où ces lignes sont écrites), car ld et la bibliothèque standard font vraiment beaucoup de choses au démarrage du programme. Mais nous pouvons exploiter ici le fait qu’il se passe très peu de choses au moment de l’arrêt du programme (peu de variables globales avec des destructeurs), sauter directement à la fin de la sortie avec la touche “Fin” de notre clavier, et remonter avec la touche “page précédente” jusqu’à la fonction main, qui n’est pas bien loin en comparaison.

Sortie de perf script --call-trace autour de main

Sur des exécutions plus complexes où cette astuce ne marcherait plus, il faudrait utiliser un outil d’analyse de texte (grep, script python…) pour repérer la région qui nous intéresse.

Notez, au sein de la fonction main, une longue période de temps sans appel à une fonction (la boucle de calcul), où l’on ne voit que des “paquets PSB” (points de repère utilisés pour l’avance rapide dans le fichier et la récupération de données partiellement corrompues), des événements de changement de fréquence d’horloge CPU, et des rappels réguliers du nom de la fonction active (main) dont la raison d’être n’est pas claire pour l’auteur de ce TP.

Une fois la fonction main repérée, nous pouvons repérer la valeur de l’horloge juste avant qu’on rentre dans la boucle de calcul (ce qu’on repère par une longue période de temps sans appel à d’autres fonctions) et juste après la fin de la boucle de calcul (ce qu’on repère par la libération de structures de données avec free). Puis on peut relancer la vue détaillée perf script --insn-trace --xed en ciblant cette fenêtre de temps avec l’option --time :

# ATTENTION: Adaptez la fenêtre de temps à vos données !
perf script --insn-trace --xed --time 402890.894663115,402890.961054471

L’horloge TSC étant relativement peu précise quand on travaille à l’échelle de l’instruction CPU unique, il faut scroller un peu pour arriver à la fin de l’initialisation des vecteurs et au début de la boucle de calcul, mais on finit quand même par trouver notre bonheur :

Sortie de perf script --insn-trace --xed autour du calcul

(Notez qu’il est possible que les instructions diffèrent un peu sur votre écran si vous avez fait les exercices du TP sur perf annotate)

Exercice : Répétez le processus en utilisant cette fois un nombre d’itérations de boucle interne (premier paramètre de l’exemple scale.bin) qui n’est pas multiple de la taille de vecteur SIMD (8 flottants en mode AVX), et observez comment cela affecte les instructions exécutées. Attention à ne pas trop augmenter la taille du calcul ce faisant…

Affichages simplifiés

Nous avons vu précédemment qu’il est possible d’afficher un résumé des données issues de Intel PT qui se limite aux appels de fonction non inlinés et à quelques autres événements avec l’option --call-trace. Ce n’est pas le seul type d’affichage simplifié disponible.

Tout d’abord, il existe une variant de --call-trace appelée --call-ret-trace qui permet d’afficher une ligne par retour d’une fonction en plus des lignes d’appels de fonction. Cela peut être utile quand une fonction appelle transitivement beaucoup d’autres fonctions, ainsi que pour interpréter des traces exotiques contenant des appels de fonction “sans retour” (ex: coroutines).

perf script --call-ret-trace
Début de la sortie de perf script --call-ret-trace

Notez les événements tr start et tr end qui représentent les moments où l’enregistrement démarre et s’arrête, typiquement en raison d’un changement de contexte (rappelez-vous que nous n’enregistrons pas l’activité du noyau dans notre exemple).

La plupart des autres affichages simplifiés disponibles passent par l’option --itrace, documentée dans la page de man perf-intel-pt, rubrique PERF SCRIPT, sous-rubrique New --itrace option.

Celle-ci permet entre autres de se limiter à l’affichage des instructions i, des branchements b (ou plus spécifiquement des appels c et/ou retours r de fonction), des transactions x (au sens Intel TSX), et des événements de gestion de l’énergie p (typiquement changement de fréquence d’horloge + paquets PSB). Ces lettres peuvent être combinées pour afficher plusieurs de ces événements sans afficher la totalité des événements.

On peut également demander, pour les événements sélectionnés, demander d’afficher des piles d’appels g pour mieux situer où l’événement se produit, et demander avec s<N> où <N> est à remplacer par un nombre que les N premiers événements soient ignorés (typiquement pour ne pas décoder et afficher la phase d’initialisation). Encore une fois, cette liste n’est pas exhaustive.

Le possibilité d’afficher chaque instruction enregistrée avec i peut sembler a peu près redondante par rapport à l’option exhaustive --insn-trace, mais elle prend tout son sens quand on la combine avec une sous-option qui permet de n’afficher qu’un échantillon des instructions enregistrées, extrait à la fréquence de son choix.

Par exemple, --itrace=i1ms n’affiche qu’une instruction toutes les millisecondes. Les autres unités disponibles sont us pour les microsecondes, ns pour les nanosecondes, t à chaque pas de l’horloge utilisée, et i pour afficher une instruction toutes les N instructions.

Cette fonctionnalité permet de simuler l’effet d’un profilage CPU à une fréquence bien supérieure au maximum autorisé par perf record (quelques dizaines de kHz), et ainsi d’obtenir des données d’une qualité statistique inaccessible par d’autres moyens. Ce qui a particulièrement du sens quand on visualise les données non pas avec perf script, mais avec perf report.

Intégration à perf report

Les événements générés par une certaine configuration de --itrace peuvent être visualisés non pas sous forme de séquence temporelle, mais d’histogramme/profil, en passant cette option à perf report. En voici un exemple qui affiche un rapport sur les instructions de branchement :

perf report --itrace=b

Après un temps de traitement, perf nous invite à choisir l’événement qu’on veut afficher avec une invite où il n’y a qu’un seul choix raisonnable. Gageons que l’ergonomie sera améliorée un jour…

Choix d’événement

…puis, si on sélectionne l’événement “branches”, on se retrouve face à une liste des fonctions du programme triée par nombres de branchements…

Choix de fonction

…et on peut annoter main pour voir les branchements liés à la boucle de calcul :

Répartition des branches dans l'assembleur de main

Tout se passe donc comme si on avait fait un perf record -e branches sauf que cette fois les données sont une représentation exacte de l’exécution du programme au lieu d’être une estimation statistique basée sur un échantillonage.

Exercice : Avec les instructions, la possibilité d’échantillonner à la fréquence temporelle de son choix permet d’avoir un traitement plus rapide tout en conservant une qualité statistique du résultat très supérieure à ce qui peut être obtenu par l’utilisation normale de perf record.

Utilisez la syntaxe --itrace=i<période> abordée ci-dessus pour obtenir un profil en nombre d’instructions exécutées de la boucle de calcul simulant une fréquence d’échantillonage de 1 MHz (1µs entre chaque échantillon). Remarquez l’excellente qualité statistique du résultat (prévisible en l’occurence, donc vérifiable), bien que l’exécution enregistrée ait duré moins de 100ms : elle est équivalente à celle qui aurait été obtenue en échantillonnant à 10kHz pendant 10s !

Paramètres d’acquisition

Nous arrivons à la fin de ce tour d’horizon de ce qu’il est possible de faire avec Intel PT et perf. Pour conclure, explorons un peu quels genre de paramètres peuvent être passés en argument de l’événement intel_pt// (entre les deux signes /).

La syntaxe générale est de donner le nom de chaque paramètre souhaité, éventuellement suivi du signe = et de la valeur qu’on veut lui donner (sinon une valeur par défaut spécifiée dans la documentation), puis on continue avec les autres paramètres éventuels en séparant par des virgules. Par exemple, avec cette syntaxe, les paramètres par défauts s’écrivent : intel_pt/tsc,noretcomp=0/ (activer l’option tsc, donner la valeur 0 à l’option noretcomp).

Les paramètres disponibles dépendent du modèle de CPU que l’on utilise. On peut les répartir en quelques grandes catégories :

  • Le choix de l’horloge utilisé. On l’a vu, l’horloge TSC a une granularité un peu grossière pour du profilage à la granularité de l’instruction CPU unique, c’est pourquoi d’autres horloges plus précises sont donc disponibles sur certains modèles de CPU :
    • L’horloge cyc, si elle est disponible, est précise au cycle CPU près
    • L’horloge mtc, si elle est disponible, offre une précision intermédiaire entre cyc et tsc.
  • La désactivation de certaines mesures :
    • Le relevé d’horloge (pas nécessaire si on veut juste la séquence d’instructions)
    • Le suivi des branches
    • L’instruction PTWRITE (qui permet au programme en cours d’exécution d’injecter des données de son choix dans le flux Intel PT)
    • Les événements de gestion de l’énergie (ex : changements de fréquence CPU)
  • La fréquence à laquelle certains relevés sont fait, notamment celui des horloges non-TSC et celui des paquets PSB qui représentent des points de départ possibles pour le décodage et des points de récupération en cas d’erreur d’acquisition.
  • Les options noretcomp et fup_on_ptw qui permettent d’enregistrer des détails supplémentaires, respectivement pour améliorer la résilience aux erreurs d’acquisition et pour mieux localiser la position des instructions PTWRITE dans le flux d’instruction.

Pour plus de détails sur ces paramètres et la détection de leur présence ou non sur le CPU utilisé, voir la page de man perf-intel-pt, rubrique PERF RECORD, sous-rubrique config terms.

Plus généralement, la lecture de l’ensemble de cette page de man est recommandée pour plus d’informations sur Intel PT et son intégration à perf, cette section de TP n’étant qu’une introduction aux possibilités offertes par l’outil.