Comprendre Systrace

Systrace est le principal outil d'analyse des performances des appareils Android. Cependant, c'est en fait un wrapper pour d'autres outils. Il s'agit du wrapper côté hôte autour d'atrace, l'exécutable côté appareil qui contrôle l'espace utilisateur et configure ftrace, ainsi que le mécanisme de traçage principal sous Linux noyau. Systrace utilise atrace pour activer le traçage, puis lit le tampon ftrace et l'encapsule dans un lecteur HTML autonome. (Bien que les noyaux plus récents prennent en charge pour le filtre eBPF (Advanced Berkeley Packet Filter) Linux), la documentation suivante concerne le noyau 3.18 (sans eFPF), car c'est celui utilisé sur le Pixel/Pixel XL.)

Systrace, qui appartient aux équipes Google Android et Google Chrome, est Open Source dans le cadre Projet catapulte. Dans en plus de Systrace, Catapult comprend d'autres utilitaires utiles. Par exemple : ftrace offre plus de fonctionnalités que celles pouvant être activées directement par Systrace ou atrace et contient des fonctionnalités avancées essentielles au débogage des performances des problèmes. (Ces fonctionnalités nécessitent un accès racine et souvent un nouveau noyau.)

Exécuter Systrace

Lors du débogage de la gigue sur un Pixel/Pixel XL, commencez par ce qui suit :

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

Lorsqu'elle est combinée aux points de trace supplémentaires requis pour le GPU et l'affichage l'activité du pipeline, ce qui vous permet de tracer de l'entrée utilisateur à la trame. affiché à l'écran. Définissez une taille de mémoire tampon élevée pour éviter de perdre (car sans mémoire tampon importante, certains processeurs ne contiennent aucun événement après un certain point de la trace).

Lorsque vous passez par Systrace, gardez à l'esprit que chaque événement est déclenché par un élément du CPU.

Comme Systrace s'appuie sur ftrace et que ftrace s'exécute sur le processeur, quelque chose sur le CPU 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 s'exécutait sur le CPU au moment exact de sa transition (quelque chose en cours d'exécution sur le CPU a déclenché une modification dans le journal). Ce est la base de l'analyse des performances à l'aide de Systrace.

Exemple: cadre de travail

Cet exemple décrit une trace Systrace pour un pipeline d'UI normal. Pour suivre avec l'exemple, téléchargez le fichier ZIP contenant les 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. Recevoir un avertissement que ce fichier Systrace est volumineux, sauf si vous utilisez Systrace il s'agit probablement d'une trace beaucoup plus grande avec beaucoup plus d'informations que ce que vous avez jamais vu dans une seule trace auparavant.

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

  1. EventThread dans SurfaceFlinger active le thread UI de l'application pour signaler qu'il est temps pour afficher un nouveau cadre.
  2. L'application affiche un frame dans le thread UI, RenderThread et hwuiTasks, en utilisant le processeur et de ressources GPU. Il s'agit de la majeure partie de la capacité dépensée pour l'interface utilisateur.
  3. L'application envoie le frame affiché à SurfaceFlinger à l'aide d'un binder, puis SurfaceFlinger se met en veille.
  4. Un deuxième EventThread dans SurfaceFlinger active SurfaceFlinger pour déclencher de composition et d'affichage. Si SurfaceFlinger détermine qu'il n'y a pas de travail elle se remet en veille.
  5. SurfaceFlinger gère la composition à l'aide de Hardware Composer (HWC)/Hardware Composer 2 (HWC2) ou GL. Composition HWC/HWC2 est plus rapide et consomme moins d'énergie, mais présente des limites selon le système de la puce (SoC). Cette opération prend généralement entre 4 et 6 ms, mais peut chevaucher l'étape 2, car Android les applications sont toujours mises en mémoire tampon trois fois. (Bien que les applications soient toujours mises en mémoire tampon trois fois, peut n'être qu'une image en attente dans SurfaceFlinger, ce qui fait apparaître identique à la mise en mémoire tampon double.)
  6. SurfaceFlinger envoie la sortie finale à afficher avec un pilote de fournisseur et fait dans l'attente de l'activation d'EventThread.

Examinons le cadre commençant à 15 409 ms:

<ph type="x-smartling-placeholder">
</ph> <ph type="x-smartling-placeholder"></ph> Pipeline UI normal avec EventThread en cours d&#39;exécution <ph type="x-smartling-placeholder">
</ph> Figure 1 : Pipeline UI normal, EventThread en cours d'exécution

La figure 1 est une image normale entourée de cadres normaux. Il s'agit donc d'une bonne point de départ pour comprendre le fonctionnement du pipeline d'UI. Ligne du thread UI pour la latence tactile comprend différentes couleurs à différents moments. Les barres indiquent états différents pour le thread:

  • Gris : Dormir.
  • Bleu. exécutable (il pourrait s'exécuter, mais le programmeur n'a pas l'avoir sélectionnée pour être exécutée).
  • Vert. Exécution active (le planificateur pense en cours d'exécution).
  • Rouge. Sommeil ininterrompu (en général, dormant sur une serrure dans le noyau). Peut indiquer une charge d'E/S. Extrêmement utile pour le débogage les problèmes de performances.
  • Orange. Veille ininterrompue en raison de la charge d'E/S.

Pour voir la raison d'une mise en veille ininterrompue (disponible à partir des sched_blocked_reason), sélectionnez l'ininterrompu rouge tranche de sommeil.

Pendant l'exécution d'EventThread, le thread UI de TouchLatency devient exécutable. Pour voir ce qui l'a réveillé, cliquez sur la partie bleue.

<ph type="x-smartling-placeholder">
</ph> <ph type="x-smartling-placeholder"></ph> Thread UI pour TouchLatency <ph type="x-smartling-placeholder">
</ph> Figure 2 : Thread UI pour TouchLatency

La figure 2 montre que le thread UI TouchLatency a été activé par tid 6843, qui correspond à EventThread. Le thread UI s'active, affiche un frame et met en file d'attente pour que SurfaceFlinger puisse l'utiliser.

<ph type="x-smartling-placeholder">
</ph> <ph type="x-smartling-placeholder"></ph> Le thread UI s&#39;active, affiche une image et la met en file d&#39;attente pour que SurfaceFlinger l&#39;utilise <ph type="x-smartling-placeholder">
</ph> Figure 3 : Le thread UI active, affiche un frame et le met en file d'attente que SurfaceFlinger utilise

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

<ph type="x-smartling-placeholder">
</ph> <ph type="x-smartling-placeholder"></ph> <ph type="x-smartling-placeholder">
</ph> Figure 4 : Transaction de liaison

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

Pendant l'utilisation de queueBuffer du côté de SurfaceFlinger, le nombre d'instances en attente images de TouchLatence passe de 1 à 2.

<ph type="x-smartling-placeholder">
</ph> <ph type="x-smartling-placeholder"></ph> Les images en attente passent de 1 à 2 <ph type="x-smartling-placeholder">
</ph> Figure 5 : Les images en attente passent de 1 à 2

La figure 5 illustre la mise en mémoire tampon triple, avec deux images terminées et la l'application est sur le point de commencer à afficher un troisième. En effet, nous avons déjà abandonné certains cadres. L'application conserve donc deux images en attente au lieu d'une pour essayer d'éviter d'autres pertes de frames.

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

<ph type="x-smartling-placeholder">
</ph> <ph type="x-smartling-placeholder"></ph> Le thread principal de SurfaceFlinger est activé par un deuxième EventThread <ph type="x-smartling-placeholder">
</ph> Figure 6 : Le thread principal de SurfaceFlinger est activé d'une seconde Thread d'événements

SurfaceFlinger verrouille d'abord l'ancien tampon en attente, ce qui entraîne passer de 2 à 1 pour le nombre de tampons en attente.

<ph type="x-smartling-placeholder">
</ph> <ph type="x-smartling-placeholder"></ph> SurfaceFlinger se fixe d&#39;abord à l&#39;ancien tampon en attente <ph type="x-smartling-placeholder">
</ph> Figure 7 : SurfaceFlinger s'attache à l'ancien en attente tampon

Après avoir verrouillé le tampon, SurfaceFlinger configure la composition et envoie le la dernière image à l'écran. (Certaines de ces sections sont activées mdss. Il est donc possible qu'ils ne soient pas inclus dans votre SoC.)

<ph type="x-smartling-placeholder">
</ph> <ph type="x-smartling-placeholder"></ph> SurfaceFlinger configure la composition et envoie le frame final <ph type="x-smartling-placeholder">
</ph> Figure 8 : SurfaceFlinger configure la composition et envoie le image finale

Ensuite, mdss_fb0 s'active sur le processeur 0. mdss_fb0 est le thread du noyau du pipeline d'affichage pour générer une image affichée sur l'écran. mdss_fb0 apparaît sur sa propre ligne dans la trace (faites défiler l'écran vers le bas jusqu'à vue).

<ph type="x-smartling-placeholder">
</ph> <ph type="x-smartling-placeholder"></ph> Activation de mdss_fb0 sur le processeur 0 <ph type="x-smartling-placeholder">
</ph> Figure 9 : activation de mdss_fb0 sur le processeur 0

mdss_fb0 se réveille, court brièvement, entre en mode veille sans interruption, puis se réveille à nouveau.

Exemple: Cadre non fonctionnel

Cet exemple décrit une trace Systrace utilisée pour déboguer la gigue du Pixel/Pixel XL. À suivez l'exemple : téléchargez le fichier ZIP fichier de traces (y compris les autres traces mentionnées dans ce décompressez le fichier, puis ouvrez le fichier systrace_tutorial.html dans votre navigateur.

Lorsque vous ouvrez Systrace, un résultat semblable au suivant s'affiche:

<ph type="x-smartling-placeholder">
</ph> <ph type="x-smartling-placeholder"></ph> Latence tactile exécutée sur un Pixel XL avec la plupart des options activées <ph type="x-smartling-placeholder">
</ph> Figure 10 : Latence tactile exécutée sur un Pixel XL (la plupart des options) y compris les tracepoints mdss et kgsl)

Si vous recherchez les à-coups, vérifiez la ligne "FrameFailed" sous SurfaceFlinger. FrameFailed est une technologie d'amélioration de la qualité de vie fournie par HWC2. Lors de la consultation Systrace pour les autres appareils, la ligne "FrameFailed" peut ne pas être présente si l'appareil n'utilise pas HWC2. Dans l'un ou l'autre dans le cas contraire, il y a une corrélation entre FrameMissing et SurfaceFlinger manquant. des environnements d'exécution extrêmement standards et un nombre de tampons en attente inchangé pour l'application. (com.prefabulated.touchlatency) sur vsync.

<ph type="x-smartling-placeholder">
</ph> <ph type="x-smartling-placeholder"></ph> Corrélation FrameMissing avec SurfaceFlinger <ph type="x-smartling-placeholder">
</ph> Figure 11 : Corrélation FrameMissing avec SurfaceFlinger

La figure 11 illustre une trame manquée à 15 598,29 ms. SurfaceFlinger s'est brièvement réveillé à l'intervalle vsync et se sont remis en veille sans rien faire, ce qui signifie SurfaceFlinger a déterminé qu'il ne valait pas la peine d'essayer d'envoyer un frame à l'écran à nouveau. Pourquoi ?

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

<ph type="x-smartling-placeholder">
</ph> <ph type="x-smartling-placeholder"></ph> SurfaceFlinger s&#39;active et se met immédiatement en veille <ph type="x-smartling-placeholder">
</ph> Figure 12 : SurfaceFlinger s'active et passe immédiatement à sommeil

Comme nous avons des cadres dans SurfaceFlinger, il ne s'agit pas d'un problème d'application. De plus, SurfaceFlinger s'active au bon moment, il ne s'agit donc pas d'un SurfaceFlinger problème. Si SurfaceFlinger et l'application semblent tous deux normaux, il s'agit probablement problème de pilote.

Comme 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 à quel moment les images sont envoyées à l'écran. Ces clôtures sont répertoriées sous mdss_fb0_retire, qui indique quand une image s'affiche à l'écran. Ces clôtures sont fournies comme de la catégorie de trace sync. À quelles clôtures correspondent des événements particuliers dans SurfaceFlinger dépendent de votre SOC et de votre pile de pilotes. Collaborez avec votre fournisseur SOC pour comprendre la signification des catégories de clôtures et des traces, etc.

<ph type="x-smartling-placeholder">
</ph> <ph type="x-smartling-placeholder"></ph> mdss_fb0_retirer clôtures <ph type="x-smartling-placeholder">
</ph> Figure 13 : mdss_fb0_retire fences

La figure 13 montre une image affichée pendant 33 ms, et non 16,7 ms comme prévu. Au milieu de cette tranche, ce cadre aurait dû être remplacé par un nouveau mais ce n'est pas le cas. Affichez le cadre précédent et recherchez ce que vous voulez.

<ph type="x-smartling-placeholder">
</ph> <ph type="x-smartling-placeholder"></ph> Image précédant l&#39;image détruite <ph type="x-smartling-placeholder">
</ph> Figure 14 : Image précédant l'image détruite

La figure 14 représente une image de 14,482 ms. Le segment à deux images cassé durait 33,6 ms, ce qui correspond à peu près à ce qu'on attendait pour deux images (le rendu avec une fréquence de 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 qu'il y a un problème très important avec le tuyau d'affichage.

Étudiez l'endroit exact où cette clôture s'arrête pour déterminer ce qui la contrôle.

<ph type="x-smartling-placeholder">
</ph> <ph type="x-smartling-placeholder"></ph> Examiner l&#39;extrémité de la clôture <ph type="x-smartling-placeholder">
</ph> Figure 15 : Examiner l'extrémité de la clôture

Une file d'attente contient __vsync_retire_work_handler, qui est en cours d'exécution lorsque la clôture change. En parcourant la source du noyau, vous pouvez voir que elle fait partie du pilote d'affichage. Il semble qu'il se trouve sur pour le pipeline d'affichage, il doit donc s'exécuter aussi rapidement que possible. Il est exécutable pour 70 US environ (pas un long délai de planification), mais il s'agit d'une file d'attente et peuvent ne pas être planifiés avec précision.

Examinez l'image précédente pour voir si cela a contribué. parfois gigue peuvent s'accumuler au fil du temps et éventuellement entraîner un retard d'échéance.

<ph type="x-smartling-placeholder">
</ph> <ph type="x-smartling-placeholder"></ph> Cadre précédent <ph type="x-smartling-placeholder">
</ph> Figure 16 : Cadre précédent

La ligne exécutable sur le nœud de calcul n'est pas visible, car l'utilisateur la transforme blanc quand il est sélectionné, mais les statistiques en disent long: 2,3 ms de planificateur le retard d'une partie du chemin critique du pipeline d'affichage est mauvais. Avant de continuer, corrigez le délai en déplaçant cette partie de la afficher le chemin critique du pipeline depuis une file d'attente (qui s'exécute SCHED_OTHER thread CFS) vers un SCHED_FIFO dédié kthread. Cette fonction a besoin de garanties temporelles que vous êtes censé fournir.

Est-ce la raison de ces à-coups ? Il est difficile de le dire de manière concluante. En dehors de les cas faciles à diagnostiquer, tels que les conflits de verrouillage du noyau entraînant des problèmes d’affichage les fils de discussion, les traces ne précisent généralement pas le problème. Cette gigue peut-elle être à l'origine de la perte de trame ? Absolument. La Les durées de cloisonnement doivent être de 16,7 ms, mais elles ne s'en approchent pas du tout dans les cadres. avant l'abandon de la trame. Compte tenu du couplage fort du pipeline d'affichage il est possible que la gigue autour de la durée de la clôture ait entraîné une chute cadre.

Dans cet exemple, la solution consistait à convertir __vsync_retire_work_handler d'une file d'attente vers une kthread. Cela a entraîné une nette amélioration de la gigue et une réduction des à-coups dans test d'une balle rebondissante. Les traces suivantes montrent des durées de cloisonnement très proches à 16,7 ms.