Comprendre Systrace

systrace est le principal outil d'analyse des performances des appareils Android. Cependant, il s’agit en réalité d’une enveloppe autour d’autres outils. Il s'agit du wrapper côté hôte autour de atrace , de l'exécutable côté périphérique qui contrôle le traçage de l'espace utilisateur et configure ftrace , et du mécanisme de traçage principal du noyau Linux. systrace utilise atrace pour activer le traçage, puis lit le tampon ftrace et enveloppe le tout dans une visionneuse HTML autonome. (Bien que les noyaux les plus récents prennent en charge le filtre de paquets Linux Enhanced Berkeley Packet Filter (eBPF), la documentation suivante concerne le noyau 3.18 (pas d'eFPF), car c'est ce qui a été utilisé sur le Pixel/Pixel XL.)

systrace appartient aux équipes Google Android et Google Chrome et est open source dans le cadre du projet Catapult . En plus de systrace, Catapult comprend d'autres utilitaires utiles. Par exemple, ftrace possède plus de fonctionnalités que ce qui peut être directement activé par systrace ou atrace et contient des fonctionnalités avancées essentielles au débogage des problèmes de performances. (Ces fonctionnalités nécessitent un accès root et souvent un nouveau noyau.)

Exécution d'une trace système

Lors du débogage de la gigue sur Pixel/Pixel XL, démarrez avec la commande suivante :

./systrace.py sched freq idle am wm gfx view sync binder_driver irq workq input -b 96000

Lorsqu'il est combiné avec les points de trace supplémentaires requis pour l'activité du GPU et du pipeline d'affichage, cela vous donne la possibilité d'effectuer un suivi depuis l'entrée de l'utilisateur jusqu'à l'image affichée à l'écran. Définissez la taille du tampon sur quelque chose de grand pour éviter de perdre des événements (car sans un tampon important, certains processeurs ne contiennent aucun événement après un certain point dans la trace).

Lorsque vous parcourez systrace, gardez à l'esprit que chaque événement est déclenché par quelque chose sur le CPU .

Étant donné que systrace est construit sur ftrace et que ftrace s'exécute sur le processeur, quelque chose sur le processeur doit écrire le tampon ftrace qui enregistre les modifications matérielles. Cela signifie que si vous êtes curieux de savoir pourquoi une clôture d'affichage a changé d'état, vous pouvez voir ce qui était en cours d'exécution sur le processeur au moment exact de sa transition (quelque chose en cours d'exécution sur le processeur a déclenché ce changement dans le journal). Ce concept constitue la base de l'analyse des performances à l'aide de systrace.

Exemple : cadre de travail

Cet exemple décrit une trace système pour un pipeline d'interface utilisateur normal. Pour suivre l'exemple, téléchargez le fichier zip des traces (qui inclut également d'autres traces mentionnées dans cette section), décompressez le fichier et ouvrez le fichier systrace_tutorial.html dans votre navigateur. Soyez averti que cette trace système est un fichier volumineux ; à moins que vous n'utilisiez systrace dans votre travail quotidien, il s'agit probablement d'une trace beaucoup plus volumineuse avec beaucoup plus d'informations que vous n'en avez jamais vue auparavant.

Pour une charge de travail cohérente et périodique telle que TouchLatency, le pipeline de l'interface utilisateur contient les éléments suivants :

  1. EventThread dans SurfaceFlinger réveille le thread de l'interface utilisateur de l'application, signalant qu'il est temps de restituer une nouvelle image.
  2. L'application restitue une image dans le thread d'interface utilisateur, RenderThread et hwuiTasks, en utilisant les ressources CPU et GPU. Il s’agit de la majeure partie de la capacité dépensée pour l’interface utilisateur.
  3. L'application envoie l'image rendue à SurfaceFlinger à l'aide d'un classeur, puis SurfaceFlinger se met en veille.
  4. Un deuxième EventThread dans SurfaceFlinger réveille SurfaceFlinger pour déclencher la composition et afficher la sortie. Si SurfaceFlinger détermine qu’il n’y a aucun travail à effectuer, il se rendort.
  5. SurfaceFlinger gère la composition à l'aide de Hardware Composer (HWC)/Hardware Composer 2 (HWC2) ou GL. La composition HWC/HWC2 est plus rapide et consomme moins, mais présente des limites en fonction du système sur puce (SoC). Cela prend généralement environ 4 à 6 ms, mais peut chevaucher l'étape 2, car les applications Android sont toujours mises en triple mémoire tampon. (Bien que les applications soient toujours mises en triple mémoire tampon, il ne peut y avoir qu'une seule image en attente dans SurfaceFlinger, ce qui la fait apparaître identique à la double mise en mémoire tampon.)
  6. SurfaceFlinger distribue la sortie finale à afficher avec un pilote du fournisseur et se rendort en attendant le réveil d'EventThread.

Parcourons l'image commençant à 15 409 ms :

Pipeline d'interface utilisateur normal avec EventThread en cours d'exécution
Figure 1. Pipeline d'interface utilisateur normal, EventThread en cours d'exécution

La figure 1 est un cadre normal entouré de cadres normaux, c'est donc un bon point de départ pour comprendre le fonctionnement du pipeline de l'interface utilisateur. La ligne de fil de discussion de l'interface utilisateur pour TouchLatency comprend différentes couleurs à différents moments. Les barres indiquent différents états du thread :

  • Gris . Dormir.
  • Bleu. Exécutable (il pourrait s'exécuter, mais le planificateur ne l'a pas encore choisi pour s'exécuter).
  • Vert. En cours d'exécution (le planificateur pense qu'il est en cours d'exécution).
  • Rouge. Sommeil ininterrompu (généralement en veille sur un verrou du noyau). Peut être révélateur de la charge d’E/S. Extrêmement utile pour déboguer les problèmes de performances.
  • Orange. Veille ininterrompue en raison de la charge d'E/S.

Pour afficher la raison du sommeil ininterrompu (disponible à partir du point de trace sched_blocked_reason ), sélectionnez la tranche de sommeil ininterrompu rouge.

Pendant l'exécution d'EventThread, le thread d'interface utilisateur pour TouchLatency devient exécutable. Pour voir ce qui l'a réveillé, cliquez sur la section bleue.

Fil de discussion de l'interface utilisateur pour TouchLatency
Figure 2. Fil de l'interface utilisateur pour TouchLatency

La figure 2 montre que le thread de l'interface utilisateur TouchLatency a été réveillé par le tid 6843, ce qui correspond à EventThread. Le thread de l'interface utilisateur se réveille, restitue une image et la met en file d'attente pour que SurfaceFlinger la consomme.

Le thread d'interface utilisateur se réveille, restitue une image et la met en file d'attente pour que SurfaceFlinger la consomme
Figure 3. Le thread de l'interface utilisateur se réveille, restitue une image et la met en file d'attente pour que SurfaceFlinger la consomme

Si la balise binder_driver est activée dans une trace, vous pouvez sélectionner une transaction de classeur pour afficher des informations sur tous les processus impliqués dans cette transaction.

Figure 4. Transaction de classeur

La figure 4 montre qu'à 15 423,65 ms, Binder:6832_1 dans SurfaceFlinger devient exécutable en raison du tid 9579, qui est le RenderThread de TouchLatency. Vous pouvez également voir queueBuffer des deux côtés de la transaction du classeur.

Pendant le queueBuffer côté SurfaceFlinger, le nombre de frames en attente de TouchLatency passe de 1 à 2.

Les images en attente passent de 1 à 2
Figure 5. Les trames en attente passent de 1 à 2

La figure 5 montre la triple mise en mémoire tampon, où il y a deux images terminées et l'application est sur le point de commencer à en restituer une troisième. En effet, nous avons déjà supprimé certaines images. L'application conserve donc deux images en attente au lieu d'une pour essayer d'éviter d'autres images perdues.

Peu de temps après, le thread principal de SurfaceFlinger est réveillé par un deuxième EventThread afin qu'il puisse afficher l'ancienne image en attente à l'écran :

Le thread principal de SurfaceFlinger est réveillé par un deuxième EventThread
Figure 6. Le thread principal de SurfaceFlinger est réveillé par un deuxième EventThread

SurfaceFlinger verrouille d'abord l'ancien tampon en attente, ce qui entraîne une diminution du nombre de tampons en attente de 2 à 1.

SurfaceFlinger se verrouille d'abord sur l'ancien tampon en attente
Figure 7. SurfaceFlinger se verrouille d'abord sur l'ancien tampon en attente

Après avoir verrouillé le tampon, SurfaceFlinger configure la composition et soumet l'image finale à l'affichage. (Certaines de ces sections sont activées dans le cadre du point de trace mdss , elles peuvent donc ne pas être incluses sur votre SoC.)

SurfaceFlinger configure la composition et soumet l'image finale
Figure 8. SurfaceFlinger configure la composition et soumet l'image finale

Ensuite, mdss_fb0 se réveille sur le processeur 0. mdss_fb0 est le thread du noyau du pipeline d'affichage pour afficher une image rendue à l'écran. Nous pouvons voir mdss_fb0 comme sa propre ligne dans la trace (faites défiler vers le bas pour voir).

mdss_fb0 se réveille sur le processeur 0
Figure 9. mdss_fb0 se réveille sur le processeur 0

mdss_fb0 se réveille, s'exécute brièvement, entre en veille ininterrompue, puis se réveille à nouveau.

Exemple : cadre non fonctionnel

Cet exemple décrit une trace système utilisée pour déboguer la gigue Pixel/Pixel XL. Pour suivre l'exemple, téléchargez le fichier zip des traces (qui inclut d'autres traces mentionnées dans cette section), décompressez le fichier et ouvrez le fichier systrace_tutorial.html dans votre navigateur.

Lorsque vous ouvrez le systrace, vous verrez quelque chose comme ceci :

TouchLatency fonctionnant sur Pixel XL avec la plupart des options activées
Figure 10. TouchLatency exécuté sur Pixel XL (la plupart des options sont activées, y compris les points de trace mdss et kgsl)

Lorsque vous recherchez des fichiers indésirables, vérifiez la ligne FrameMissed sous SurfaceFlinger. FrameMissed est une amélioration de la qualité de vie fournie par HWC2. Lors de l'affichage du systrace pour d'autres appareils, la ligne FrameMissed peut ne pas être présente si l'appareil n'utilise pas HWC2. Dans les deux cas, FrameMissed est corrélé au fait que SurfaceFlinger manque l'un de ses temps d'exécution extrêmement réguliers et un nombre de tampons en attente inchangé pour l'application ( com.prefabulated.touchlatency ) lors d'une vsync.

Corrélation FrameMissed avec SurfaceFlinger
Figure 11. Corrélation FrameMissed avec SurfaceFlinger

La figure 11 montre une image manquée à 15 598,29 ms. SurfaceFlinger s'est réveillé brièvement à l'intervalle vsync et s'est rendormi sans effectuer aucun travail, ce qui signifie que SurfaceFlinger a déterminé que cela ne valait pas la peine d'essayer d'envoyer à nouveau une image à l'écran. Pourquoi?

Pour comprendre comment le pipeline s'est décomposé pour ce cadre, examinez d'abord l'exemple de cadre de travail ci-dessus pour voir comment un pipeline d'interface utilisateur normal apparaît dans systrace. Lorsque vous êtes prêt, revenez à l’image manquée et travaillez en arrière. Notez que SurfaceFlinger se réveille et se met immédiatement en veille. Lorsque vous affichez le nombre d'images en attente de TouchLatency, il y a deux images (un bon indice pour vous aider à comprendre ce qui se passe).

SurfaceFlinger se réveille et s'endort immédiatement
Figure 12. SurfaceFlinger se réveille et s'endort immédiatement

Parce que nous avons des cadres dans SurfaceFlinger, ce n'est pas un problème d'application. De plus, SurfaceFlinger se réveille au bon moment, ce n'est donc pas un problème de SurfaceFlinger. Si SurfaceFlinger et l'application semblent tous deux normaux, il s'agit probablement d'un problème de pilote.

Étant donné que les points de trace mdss et sync sont activés, nous pouvons obtenir des informations sur les clôtures (partagées entre le pilote d'affichage et SurfaceFlinger) qui contrôlent le moment où les images sont soumises à l'affichage. Ces clôtures sont répertoriées sous mdss_fb0_retire , ce qui indique le moment où un cadre est affiché. Ces clôtures sont fournies dans le cadre de la catégorie de trace sync . Les clôtures correspondant à des événements particuliers dans SurfaceFlinger dépendent de votre SOC et de votre pile de pilotes. Travaillez donc avec votre fournisseur SOC pour comprendre la signification des catégories de clôture dans vos traces.

mdss_fb0_retire clôtures
Figure 13. Clôtures mdss_fb0_retire

La figure 13 montre une trame affichée pendant 33 ms, et non 16,7 ms comme prévu. À mi-chemin de cette tranche, ce cadre aurait dû être remplacé par un nouveau, mais cela ne l'a pas été. Affichez l'image précédente et recherchez n'importe quoi.

Cadre précédant le cadre cassé
Figure 14. Cadre précédant le cadre cassé

La figure 14 montre 14,482 ms par trame. Le segment brisé de deux images était de 33,6 ms, ce qui correspond à peu près à ce à quoi nous nous attendons pour deux images (nous rendons à 60 Hz, 16,7 ms par image, ce qui est proche). Mais 14,482 ms n'est pas du tout proche de 16,7 ms, ce qui suggère que quelque chose ne va vraiment pas avec le canal d'affichage.

Enquêtez exactement où se termine cette clôture pour déterminer ce qui la contrôle.

Enquêter sur l'extrémité de la clôture
Figure 15. Enquêter sur l'extrémité de la clôture

Une file d'attente de travail contient __vsync_retire_work_handler , qui s'exécute lorsque la clôture change. En parcourant les sources du noyau, vous pouvez voir qu'il fait partie du pilote d'affichage. Il semble se trouver sur le chemin critique du pipeline d’affichage, il doit donc s’exécuter le plus rapidement possible. Il peut être exécuté pendant environ 70 heures (pas un long délai de planification), mais il s'agit d'une file d'attente de travail et il se peut qu'elle ne soit pas planifiée avec précision.

Vérifiez le cadre précédent pour déterminer si cela a contribué ; Parfois, la gigue peut s'accumuler avec le temps et éventuellement entraîner un non-respect des délais.

Image précédente
Figure 16. Cadre précédent

La ligne exécutable sur kworker n'est pas visible car le visualiseur la rend blanche lorsqu'elle est sélectionnée, mais les statistiques racontent l'histoire : 2,3 ms de retard du planificateur pour une partie du chemin critique du pipeline d'affichage sont mauvais . Avant de continuer, corrigez le délai en déplaçant cette partie du chemin critique du pipeline d'affichage d'une file d'attente de travail (qui s'exécute en tant que thread SCHED_OTHER CFS) vers un kthread SCHED_FIFO dédié. Cette fonction nécessite des garanties de timing que les files d'attente ne peuvent pas (et ne sont pas censées) fournir.

Est-ce la raison de la pagaille ? C'est difficile à dire de manière concluante. En dehors des cas faciles à diagnostiquer, tels qu'un conflit de verrouillage du noyau provoquant la mise en veille des threads critiques pour l'affichage, les traces ne spécifient généralement pas le problème. Cette gigue aurait-elle pu être la cause de la perte d'image ? Absolument. Les temps de clôture devraient être de 16,7 ms, mais ils ne sont pas du tout proches de cela dans les images menant à l'image perdue. Étant donné l'étroitesse du couplage du pipeline d'affichage, il est possible que la gigue autour des timings de clôture ait entraîné une perte d'image.

Dans cet exemple, la solution impliquait la conversion __vsync_retire_work_handler d'une file d'attente de travail en un kthread dédié. Cela a entraîné des améliorations notables de la gigue et une réduction des secousses lors du test de balle rebondissante. Les traces ultérieures montrent des timings de clôture très proches de 16,7 ms.