Google is committed to advancing racial equity for Black communities. See how.
Cette page a été traduite par l'API Cloud Translation.
Switch to English

Comprendre Systrace

systrace est le principal outil d'analyse des performances des appareils Android. Cependant, c'est vraiment une enveloppe autour d'autres outils. C'est le wrapper côté hôte autour de atrace , l'exécutable côté périphérique qui contrôle le traçage de l'espace utilisateur et configure ftrace , et le mécanisme de traçage principal dans le noyau Linux. systrace utilise atrace pour activer le traçage, puis lit le tampon ftrace et encapsule le tout dans une visionneuse HTML autonome. (Bien que les noyaux plus récents prennent en charge le filtre de paquets Berkeley amélioré Linux (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 inclut d'autres utilitaires utiles. Par exemple, ftrace possède plus de fonctionnalités que celles pouvant être directement activées par systrace ou atrace et contient des fonctionnalités avancées essentielles pour déboguer les problèmes de performances. (Ces fonctionnalités nécessitent un accès root et souvent un nouveau noyau.)

Exécution de systrace

Lors du débogage de la gigue sur Pixel / Pixel XL, commencez par 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 le GPU et l'affichage de l'activité du pipeline, cela vous donne la possibilité de tracer de l'entrée utilisateur à l'image affichée à l'écran. Définissez la taille de la mémoire tampon sur quelque chose de grand pour éviter de perdre des événements (car sans une grande mémoire tampon, certains processeurs ne contiennent aucun événement après un certain point dans la trace).

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

Étant donné que systrace est construit au-dessus de 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 fonctionnait sur le processeur au point exact de sa transition (quelque chose en cours d'exécution sur le processeur a déclenché ce changement dans le journal). Ce concept est à la base de l'analyse des performances à l'aide de systrace.

Exemple: cadre de travail

Cet exemple décrit un systrace pour un pipeline d'interface utilisateur normal. Pour suivre l'exemple, téléchargez le fichier zip de traces (qui comprend é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 ce systrace est un gros fichier; à moins que vous n'utilisiez systrace dans votre travail quotidien, il s'agit probablement d'une trace beaucoup plus grande avec beaucoup plus d'informations que vous n'en avez jamais vu dans une seule trace auparavant.

Pour une charge de travail régulière et régulière telle que TouchLatency, le pipeline d'interface utilisateur contient les éléments suivants:

  1. EventThread dans SurfaceFlinger réveille le thread d'interface utilisateur de l'application, signalant qu'il est temps de rendre une nouvelle image.
  2. L'application rend une image dans le thread d'interface utilisateur, RenderThread et hwuiTasks, à l'aide de 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 à faire, 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 moins puissante, 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 triplement tamponnées. (Bien que les applications soient toujours triples tamponnées, il ne peut y avoir qu'une seule image en attente dans SurfaceFlinger, ce qui la fait apparaître identique à la double mise en tampon.)
  6. SurfaceFlinger distribue la sortie finale à afficher avec un pilote fournisseur et se rendort, en attendant le réveil d'EventThread.

Parcourons le cadre commençant à 15409 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 d'interface utilisateur. La ligne de thread de l'interface utilisateur pour TouchLatency comprend différentes couleurs à des moments différents. Les barres indiquent différents états pour le thread:

  • Gris . En train de 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 dormant sur un verrou dans le noyau). Peut être indicatif 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 sched_blocked_reason sched_blocked_reason), sélectionnez la tranche de sommeil ininterruptible 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 d'interface utilisateur pour TouchLatency
Figure 2. Fil d'exécution de l'interface utilisateur pour TouchLatency

La figure 2 montre que le thread d'interface utilisateur TouchLatency a été réveillé par tid 6843, qui correspond à EventThread. Le thread d'interface utilisateur se réveille, rend un cadre et le met en file d'attente pour que SurfaceFlinger le consomme.

Le thread d'interface utilisateur se réveille, rend un cadre et le met en file d'attente pour que SurfaceFlinger le consomme
Figure 3. Le thread d'interface utilisateur se réveille, rend 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 binder pour afficher des informations sur tous les processus impliqués dans cette transaction.

Figure 4. Transaction de liant

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

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

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

La figure 5 montre la triple mise en mémoire tampon, où il y a deux cadres terminés et l'application est sur le point de commencer le rendu d'un troisième. En effet, nous avons déjà supprimé certaines images, de sorte que l'application conserve 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 sur 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 fait passer le 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 mdss mdss, elles peuvent donc ne pas être incluses dans votre SoC.)

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

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

mdss_fb0 se réveille sur le CPU 0
Figure 9. mdss_fb0 se réveille sur la CPU 0

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

Exemple: cadre non fonctionnel

Cet exemple décrit un systrace utilisé pour déboguer la gigue Pixel / Pixel XL. Pour suivre l'exemple, téléchargez le fichier zip de traces (qui comprend 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 fonctionnant sur Pixel XL (la plupart des options sont activées, y compris les points de trace mdss et kgsl)

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

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

La figure 11 montre une trame manquée à 15598,29 & nbps; 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é qu'il ne valait pas la peine d'essayer de renvoyer une image à l'écran. Pourquoi?

Pour comprendre comment le pipeline est tombé en panne pour cette image, commencez par examiner 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. Lors de l'affichage du 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 se met immédiatement en veille

Étant donné 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 SurfaceFlinger. Si SurfaceFlinger et l'application semblent tous les deux normaux, c'est probablement un problème de pilote.

Étant donné que les 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 , qui indique lorsqu'une image est affichée. Ces clôtures sont fournies dans le cadre de la catégorie de trace de sync . Les clôtures qui correspondent à des événements particuliers dans SurfaceFlinger dépendent de votre SOC et de votre pile de pilotes, alors travaillez avec votre fournisseur SOC pour comprendre la signification des catégories de clôtures dans vos traces.

clôtures mdss_fb0_retire
Figure 13. Clôtures mdss_fb0_retire

La figure 13 montre une trame qui a été 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 ne l'a pas été. Regardez l'image précédente et recherchez quoi que ce soit.

Cadre avant le cadre cassé
Figure 14. Cadre avant le cadre éclaté

La figure 14 montre 14,482 ms par trame. Le segment de deux images brisées était de 33,6 ms, ce qui est à peu près ce à quoi nous nous attendrions 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 pas avec le tube d'affichage.

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

Examiner l'extrémité de la clôture
Figure 15. Examinez 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 la source du noyau, vous pouvez voir qu'elle 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 est exécutable pendant environ 70 nous (pas un long délai de planification), mais c'est une file d'attente de travail et peut ne pas être planifié avec précision.

Vérifiez le cadre précédent pour déterminer si cela a contribué; parfois, la gigue peut s'accumuler au fil du temps et éventuellement provoquer une échéance manquée.

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

La ligne exécutable sur le kworker n'est pas visible car la visionneuse 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 retard 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 SCHED_FIFO SCHED_FIFO dédié. Cette fonction a besoin de garanties de synchronisation que les files d'attente de travail ne peuvent pas (et ne sont pas censées) fournir.

Est-ce la raison du jank? C'est difficile à dire de manière concluante. En dehors des cas faciles à diagnostiquer tels que la contention de verrouillage du noyau entraînant 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 supprimée. Compte tenu de l'étroitesse du couplage du pipeline d'affichage, il est possible que la gigue autour des horaires de clôture ait entraîné une perte d'image.

Dans cet exemple, la solution impliquait la conversion de __vsync_retire_work_handler d'une file d'attente de travail vers un kthread dédié. Cela a entraîné des améliorations notables de la gigue et une réduction du jank lors du test de la balle rebondissante. Les traces suivantes montrent des temps de clôture qui oscillent très près de 16,7 ms.