Systrace est l'outil principal pour analyser les performances des appareils Android. Toutefois, il s'agit en réalité d'un wrapper autour d'autres outils. Il s'agit du wrapper côté hôte autour de atrace, l'exécutable côté appareil qui contrôle le traçage de l'espace utilisateur et configure ftrace, ainsi que le mécanisme de traçage principal du noyau Linux. 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 soient compatibles avec le filtre de paquets Berkeley amélioré (eBPF) de Linux, la documentation suivante concerne le noyau 3.18 (sans eFPF), car c'est celui 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 offre plus de fonctionnalités que celles qui peuvent être directement activées 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 racine et souvent un nouveau noyau.)
Exécuter systrace
Lorsque vous déboguez le jitter sur un 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
Combiné aux points de trace supplémentaires requis pour l'activité du GPU et du pipeline d'affichage, vous pouvez effectuer un traçage depuis l'entrée utilisateur jusqu'au frame affiché à l'écran. Définissez la taille de la mémoire tampon sur une valeur élevée pour éviter de perdre des événements (car sans mémoire tampon importante, certains processeurs ne contiennent aucun événement après un certain point de la trace).
Lorsque vous examinez systrace, n'oubliez pas que chaque événement est déclenché par un élément du processeur.
Étant donné que systrace est basé sur ftrace et que ftrace s'exécute sur le processeur, un élément du processeur doit écrire le tampon ftrace qui consigne les modifications matérielles. Cela signifie que si vous souhaitez savoir pourquoi une barrière d'affichage a changé d'état, vous pouvez voir ce qui s'exécutait sur le processeur au moment exact de sa transition (un élément s'exécutant 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 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. Sachez que ce fichier systrace est volumineux. Sauf si vous utilisez systrace dans votre travail quotidien, il s'agit probablement d'une trace beaucoup plus importante, avec beaucoup plus d'informations que vous n'en avez jamais vu dans une seule trace.
Pour une charge de travail cohérente et périodique telle que TouchLatency, le pipeline d'interface utilisateur contient les éléments suivants:
- EventThread dans SurfaceFlinger réveille le thread d'UI de l'application, signalant qu'il est temps d'afficher un nouveau frame.
- L'application affiche un frame dans le thread UI, RenderThread et hwuiTasks, à l'aide de ressources de processeur et de GPU. Il s'agit de la majeure partie de la capacité utilisée pour l'interface utilisateur.
- L'application envoie le frame rendu à SurfaceFlinger à l'aide d'un liaisonneur, puis SurfaceFlinger passe en veille.
- Un deuxième EventThread dans SurfaceFlinger réveille SurfaceFlinger pour déclencher la composition et l'affichage de la sortie. Si SurfaceFlinger détermine qu'il n'y a pas de travail à effectuer, il se met à nouveau en veille.
- 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 d'énergie, mais elle présente des limites en fonction du système sur une puce (SoC). Cette opération prend généralement environ 4 à 6 ms, mais peut se chevaucher avec l'étape 2, car les applications Android sont toujours triplées. (Bien que les applications soient toujours à triple tampon, il ne peut y avoir qu'un seul frame en attente dans SurfaceFlinger, ce qui donne l'impression qu'il s'agit d'une double mise en tampon.)
- SurfaceFlinger distribue la sortie finale à afficher avec un pilote du fournisseur et se met à nouveau en veille, en attendant le réveil d'EventThread.
Examinons le frame à partir de 15 409 ms:
La figure 1 est un cadre normal entouré de cadres normaux. Il s'agit donc d'un bon point de départ pour comprendre le fonctionnement du pipeline d'interface utilisateur. La ligne de thread d'interface utilisateur pour TouchLatency inclut différentes couleurs à différents moments. Les barres indiquent différents états du thread:
- Gris Dormir.
- Bleu. Exécutable (il peut s'exécuter, mais le planificateur ne l'a pas encore sélectionné).
- Vert. En cours d'exécution (le planificateur pense qu'il s'exécute).
- Rouge. Sommeil ininterruptible (généralement en mode veille sur un verrouillage dans le noyau). Peut indiquer la charge d'E/S. Extrêmement utile pour déboguer les problèmes de performances.
- Orange. Sommeil ininterrompu en raison de la charge d'E/S.
Pour afficher le motif du sommeil ininterruptible (disponible à partir du point de trace sched_blocked_reason), sélectionnez la tranche de sommeil ininterruptible rouge.
Lorsque EventThread est en cours d'exécution, le thread UI pour TouchLatency devient exécutable. Pour voir ce qui l'a réveillé, cliquez sur la section bleue.
La figure 2 montre que le thread d'interface utilisateur TouchLatency a été réveillé par le thread 6843, qui correspond à EventThread. Le thread d'UI se réveille, affiche un frame et l'ajoute à la file d'attente pour que SurfaceFlinger l'utilise.
Si la balise binder_driver est activée dans une trace, vous pouvez sélectionner une transaction de liaison pour afficher des informations sur tous les processus impliqués dans cette transaction.
La figure 4 montre qu'à 15 423, 65 ms,Binder:6832_1 dans SurfaceFlinger devient exécutable en raison du thread 9579, qui est le thread de rendu de TouchLatency. Vous pouvez également voir queueBuffer des deux côtés de la transaction de liaison.
Lors de la mise en file d'attente de la mémoire tampon côté SurfaceFlinger, le nombre de frames en attente de TouchLatency passe de 1 à 2.
La figure 5 montre la mise en mémoire tampon triple, où il y a deux frames terminés et que l'application est sur le point de commencer à en afficher un troisième. En effet, nous avons déjà abandonné certains frames. L'application conserve donc deux frames en attente au lieu d'un pour essayer d'éviter d'autres frames abandonnés.
Peu de temps après, le thread principal de SurfaceFlinger est réveillé par un deuxième EventThread afin qu'il puisse afficher l'ancien frame en attente sur l'écran:
SurfaceFlinger verrouille d'abord la mémoire tampon en attente la plus ancienne, ce qui fait passer le nombre de mémoires tampons en attente de 2 à 1.
Après avoir verrouillé le tampon, SurfaceFlinger configure la composition et envoie le frame final à l'écran. (Certaines de ces sections sont activées dans le point de trace mdss. Il est donc possible qu'elles ne soient pas incluses sur votre SoC.)
Ensuite, mdss_fb0 se réveille sur le processeur 0. mdss_fb0 est le thread du noyau du pipeline d'affichage qui permet d'afficher un frame rendu à l'écran.
mdss_fb0 apparaît comme une ligne distincte dans la trace (faites défiler la page vers le bas pour la voir).
mdss_fb0 se réveille, s'exécute brièvement, passe en mode veille ininterruptible, puis se réveille à nouveau.
Exemple: Cadre non fonctionnel
Cet exemple décrit un systrace utilisé pour déboguer le jitter du 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 systrace, vous obtenez un résultat semblable à celui-ci:
Pour rechercher des à-coups, consultez la ligne "FrameMissed" sous SurfaceFlinger.
FrameMissed est une amélioration de la qualité de vie fournie par HWC2. Lorsque vous consultez 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é à l'absence de l'un des temps d'exécution extrêmement réguliers de SurfaceFlinger et à un nombre de tampons en attente inchangé pour l'application (com.prefabulated.touchlatency) à un vsync.
La figure 11 montre un frame manqué à 15 598,29 ms. SurfaceFlinger s'est réveillé brièvement à l'intervalle vsync et s'est remis en veille sans effectuer de travail, ce qui signifie que SurfaceFlinger a déterminé qu'il n'était pas utile d'essayer d'envoyer à nouveau un frame à l'écran. Pourquoi ?
Pour comprendre comment le pipeline s'est effondré pour ce frame, commencez par examiner 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 au frame manqué et remontez le temps. Notez que SurfaceFlinger se réveille et s'endort immédiatement. Lorsque vous consultez le nombre de frames en attente à partir de TouchLatency, il y a deux frames (un bon indice pour comprendre ce qui se passe).
Étant donné que nous avons des cadres dans SurfaceFlinger, il ne s'agit pas d'un problème d'application. De plus, SurfaceFlinger se réveille au bon moment. Il ne s'agit donc pas d'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 traçage mdss et sync sont activés, nous pouvons obtenir des informations sur les barrières (partagée entre le pilote d'affichage et SurfaceFlinger) qui contrôlent le moment où les frames sont envoyées à l'écran.
Ces barrières sont listées sous mdss_fb0_retire, qui indique quand un frame est à l'écran. Ces barrières sont fournies dans la catégorie de trace sync. Les barrières qui correspondent à des événements particuliers dans SurfaceFlinger dépendent de votre SOC et de la pile de pilotes. Par conséquent, collaborez avec votre fournisseur de SOC pour comprendre la signification des catégories de barrières dans vos traces.
La figure 13 montre un frame qui a été affiché pendant 33 ms, et non 16,7 ms comme prévu. À mi-chemin de ce segment, ce frame aurait dû être remplacé par un nouveau, mais il ne l'a pas été. Affichez le frame précédent et recherchez tout ce qui vous intéresse.
La figure 14 indique 14,482 ms par frame. Le segment de deux frames interrompu a duré 33,6 ms, ce qui correspond à peu près à ce que nous attendons pour deux frames (nous effectuons un rendu à 60 Hz, soit 16,7 ms par frame, ce qui est proche). Cependant, 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 canal d'affichage.
Déterminez exactement où cette clôture se termine pour identifier ce qui la contrôle.
Une file d'attente de travail contient __vsync_retire_work_handler, qui s'exécute lorsque la clôture change. En examinant la source 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 aussi rapidement que possible. Il peut s'exécuter pendant environ 70 µs (pas un long délai de planification), mais il s'agit d'une file d'attente de travail et il est possible qu'il ne soit pas planifié avec précision.
Vérifiez le frame précédent pour déterminer si cela a contribué. Parfois, le jitter peut s'accumuler au fil du temps et entraîner un dépassement du délai.
La ligne exécutable sur le kworker n'est pas visible, car l'outil de visualisation la fait passer au blanc lorsqu'elle est sélectionnée, mais les statistiques en disent long: 2,3 ms de retard du planificateur pour une partie du chemin critique du pipeline d'affichage est mauvais.
Avant de continuer, corrigez le délai en déplaçant cette partie du chemin critique du pipeline d'affichage d'un workqueue (qui s'exécute en tant que thread CFS SCHED_OTHER) vers un kthread SCHED_FIFO dédié. Cette fonction nécessite des garanties de synchronisation que les files d'attente de travail ne peuvent pas fournir (et ne sont pas destinées à le faire).
Est-ce la raison de ce problème ? C'est difficile de le dire de manière définitive. En dehors des cas faciles à diagnostiquer, tels que les conflits de verrouillage du noyau qui entraînent l'arrêt des threads critiques pour l'affichage, les traces ne spécifient généralement pas le problème. Ce jitter peut-il être à l'origine de la perte de frame ? Absolument. Les temps de clôture doivent être de 16,7 ms, mais ils ne s'en approchent pas du tout dans les images qui précèdent l'image supprimée. Étant donné la forte interdépendance du pipeline d'affichage, il est possible que le jitter autour des délais de clôture ait entraîné une perte de frame.
Dans cet exemple, la solution consistait à convertir __vsync_retire_work_handler d'une file d'attente de travail en kthread dédié. Cela a permis d'améliorer le jitter de manière notable et de réduire les à-coups dans le test de la balle rebondissante. Les traces suivantes montrent des délais de clôture qui se situent très près de 16,7 ms.