Tracepoints

Comme on l’a vu dans la partie sur perf annotate, perf record évalue par défaut quels régions du code consomment la plus grande quantité de cycles CPU, mais il est possible de suivre d’autres événements avec la désormais habituelle option --event/-e.

Par exemple, avec perf record -e L1-dcache-load-misses, on peut déterminer dans quelles régions du code il y a le plus de défauts de cache L1. Cela peut offrir un éclairage alternatif à la seule étude de consommation de cycles CPU, qui est utile quand on optimise l’utilisation de ressources CPU comme les caches qui sont partagées entre différentes régions du code. En effet, quand ces ressources sont sous tension, on peut observer des comportements contre-intuitifs, par exemple ajouter un nouveau module de code peut ralentir un module préexistant qui n’a pas été modifié.

Mais il y a un autre type d’événements qui est particulièrement intéressant à analyser avec perf record et perf report, c’est les événements issus du noyau Linux, comme les tracepoints.

En effet, nous avons vu que leur suivi “en direct” avec perf trace peut être parfois difficile :

• Il est facile de se retrouver submergé dans par un journal gigantesque d’événements, bien que ce journal soit souvent très redondant.
• La stratégie de perf trace d’afficher du texte à chaque fois que l’événement survient ne passe pas à l’échelle quand l’événement étudié est fréquent.
• Si l’action d’afficher du texte déclenche l’événement étudié, perf trace peut se retrouver dans une situation indésirable de récursion infinie.

Nous allons voir maintenant que l’étude de ces mêmes événements avec perf record et perf report fournit un éclairage différent qui peut aider à surmonter ces difficultés.

Appels système d’une commande

Considérons la commande suivante, qui lit des zéros depuis /dev/zero est les rejette dans /dev/null. C’est un benchmark simple de la performance des pseudofichiers du noyau Linux.

srun --pty \
    bash -c 'tail -c10G /dev/zero >/dev/null'

On l’a vu, perf trace peut nous donner un premier aperçu des appels systèmes effectués par cette commande…

srun --pty \
    perf trace -s \
    bash -c 'tail -c10G /dev/zero >/dev/null'

…et on constate sans surprise que l’essentiel de l’activité système générée et du temps d’exécution associé sont liés aux lectures et écritures du système de fichier effectuées par la commande tail.

Mais il y a aussi des choses plus surprenantes, notamment le fait que le nombre de lectures d’écritures n’est pas le même. Et on pourrait aussi se poser des questions d’implémentation, par exemple vouloir savoir si la taille des lectures et écritures en octets est toujours la même. Le mode “résumé” de perf trace que nous venons d’utiliser ne permet pas de répondre à ces questions.

A raison de millions d’appels système read et write effectués, il ne serait pas raisonnable d’afficher la liste complète de ces appels système avec perf trace et la relire manuellement. Il serait aussi laborieux d’extraire la sortie de perf trace dans un fichier et l’analyser avec un script, car elle serait très volumineuse. C’est donc un cas où perf trace n’est pas l’outil adapté.

Voyons maintenant ce que perf record et perf report peuvent nous dire sur les appels système read et write effectués par cette commande :

srun --pty \
    perf record -e '{syscalls:sys_enter_read,\
                     syscalls:sys_exit_read,\
                     syscalls:sys_enter_write,\
                     syscalls:sys_exit_write}' \
                -o /dev/shm/${USER}/perf.data \
    bash -c 'tail -c10G /dev/zero >/dev/null' \
&& mv /dev/shm/${USER}/perf.data . \
&& perf report

Nous introduisons ici une nouvelle fonctionnalité de perf record, les group events, reconaissable à sa syntaxe {} qui doit être mise dans une chaîne de caractère pour ne pas être mal interprétée par bash. Elle permet de visualiser simultanément l’activité de plusieurs événements (ici l’entrée et la sortie des appels à read et write) sous colonnes “Overhead” séparées dans perf report.

Par ailleurs, notez que le volume de données produit est si important que nous avons besoin d’utiliser /dev/shm pour stocker la sortie. Nous reviendrons sur cette question.

Nous voyons que contrairement à perf trace, perf report ne nous donne pas une liste ordonnée des appels système effectués, mais un histogramme de ceux-ci, ce qui est bien plus exploitable pour cet exemple. Il en ressort que…

• Les lectures du fichier source s’effectuent toujours au sein du même tampon, et tail demande toujours 8192 octets au noyau.
• Le noyau fournit toujours l’intégralité des 8192 octets demandés par read.
• Les écritures de fichier, elles, s’effectuent avec une granularité de 4096 octets et depuis deux tampons différents (l’un des deux étant le tampon utilisé pour read avec un décalage de +4096 octets). C’est a priori étonnant et à examiner de plus près.
• Le noyau écrit toujours l’intégralité des 4096 octets fournis à write.

En revanche, par rapport à perf trace, nous avons perdu une information importante, celle de l’ordre dans lequel se produisent les événements. C’est un compromis inhérent à la représentation en histogramme de perf report.

Nous pouvons obtenir une idée de cet ordre en étudiant un bref extrait de la très longue sortie de perf trace, après avoir indiqué à ce dernier d’attendre 100ms après le démarrage du programme pour ne pas voir la phase d’initialisation :

srun --pty \
    perf trace --delay 100 \
               -e read,write \
    bash -c 'tail -c10G /dev/zero >/dev/null' 2>&1 \
| head -n50

Et nous pourrions ensuite vouloir savoir si des chemins de code différents sont à l’origine de ces deux types d’appels différents à l’appel système write, mais avant cela il va nous falloir aborder un prérequis à ce type d’analyse…

Améliorer l’efficacité

Si vous avez fait attention aux sorties des commandes perf record précédentes, vous avez peut-être tiqué sur les volumes de données produits. Il y a deux raisons à cela :

• L’événement que nous suivons est très fréquent (plusieurs millions en quelques secondes).
• Par défaut, perf record essaye d’enregistrer chaque occurence des événements tracepoint.

Ce dernier comportement est cohérent avec celui de perf trace, mais dans le cas où nous sommes il est inadapté, car il nous fait enregistrer des millions d’événements qui sont en réalité presque tous identiques. La situation s’aggraverait encore si on essayait d’enregistrer des graphes d’appels via la méthode DWARF, puisque cela ajoute un volume de données important par échantillon.

Nous avons déjà abordé ce problème précédemment, et évoqué une solution simple : enregistrer un petit échantillon des événements étudiés, qui soit aussi statistiquement représentatif que possible. Il suffit pour cela de spécifier une fréquence d’échantillonnage avec l’option --freq/-F :

srun --pty \
    perf record -F 10000 -e syscalls:sys_enter_write \
    bash -c 'tail -c10G /dev/zero >/dev/null' \
&& perf report

Vous constaterez que du fait d’un léger biais statistique, la répartition des échantillons n’est pas de 50%/50% entre les deux appels à write. Mais le niveau de biais observé reste suffisamment faible pour que la mesure soit exploitable, et ce avec un fichier de données qui ne fait plus que 1 Mo.

En conclusion, les fréquences d’échantillonnage par défaut de perf record ne sont pas toujours adéquates (particulièrement sur les tracepoints), et il est donc recommandé de toujours évaluer rapidement la fréquence de l’événement étudié avec perf stat ou perf trace -s sur l’application cible et en déduire une valeur judicieuse pour le paramètre -F de perf report. Au bout du compte, la valeur optimale est celle…

• Qui produit une statistique suffisante.
• Qui génère un volume de données raisonnable.
• Qui perturbe aussi peu que possible l’exécution du code étudié.

Exercice : Utilisez les différentes fonctionnalités de perf report abordées précédemment (notamment --call-graph et --sort) pour répondre à la question soulevée ci-dessus : de quel code provient l’utilisation de deux tampons différents pour les écritures ?

Notez que les graphes d’appels LBR ne sont pas supportés quand on enregistre des événements tracepoint. Je ne comprends pas pourquoi (le message d’erreur n’est pas cohérent avec ce que je comprends du mode de fonctionnement du LBR), mais je peux vous dire que c’est toujours le cas dans les versions récentes de perf (6.0.7), donc c’est une limitation avec laquelle il va sans doute falloir composer dans votre pratique quotidienne de l’outil.

Rappelez-vous aussi que si vos graphes d’appels DWARF sont tronqués, vous pouvez parfois régler le problème en augmentant la taille des échantillons de pile enregistrés par perf…