systrace est le principal outil d'analyse des performances des appareils Android. Cependant, c'est vraiment un wrapper 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 du noyau Linux. systrace utilise atrace pour activer le traçage, puis lit le tampon ftrace et encapsule le tout dans un visualiseur HTML autonome. (Alors que les nouveaux noyaux prennent en charge le filtre de paquets Linux Enhanced Berkeley (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 a plus de fonctionnalités que celles qui peuvent être directement activées par systrace ou atrace et contient certaines 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.)
Systrace en cours d'exécution
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 l'activité du GPU et du pipeline d'affichage, cela vous donne la possibilité de tracer de l'entrée de l'utilisateur à 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 grand 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 CPU .
Étant donné que systrace est construit au-dessus de ftrace et que ftrace s'exécute sur le CPU, 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 point exact de sa transition (quelque chose en cours d'exécution sur le CPU 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 une systrace pour un pipeline d'interface utilisateur normal. Pour suivre l'exemple, téléchargez le fichier zip des 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 fichier volumineux ; à 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 périodique telle que TouchLatency, le pipeline d'interface utilisateur contient les éléments suivants :
- EventThread dans SurfaceFlinger réveille le thread de l'interface utilisateur de l'application, signalant qu'il est temps de restituer une nouvelle image.
- 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 l'essentiel de la capacité dépensée pour l'interface utilisateur.
- L'application envoie l'image rendue à SurfaceFlinger à l'aide d'un classeur, puis SurfaceFlinger se met en veille.
- 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 pas de travail à faire, il se rendort.
- 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 énergivore, mais présente des limitations 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. (Alors que les applications sont toujours en triple tampon, il ne peut y avoir qu'un seul cadre en attente dans SurfaceFlinger, ce qui le fait apparaître identique au double tampon.)
- SurfaceFlinger distribue la sortie finale à afficher avec un pilote de fournisseur et se remet en veille, en attendant le réveil d'EventThread.
Parcourons la trame commençant à 15409 ms :
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 fil d'interface utilisateur pour TouchLatency comprend différentes couleurs à différents moments. 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. Veille ininterruptible (dormant généralement 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 sans interruption (disponible à partir du point de sched_blocked_reason ), sélectionnez la tranche de sommeil sans interruption 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.
La figure 2 montre que le thread d'interface utilisateur TouchLatency a été réveillé par le tid 6843, ce qui correspond à EventThread. Le thread d'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.
La figure 4 montre qu'à 15 423,65 ms, Binder:6832_1 dans SurfaceFlinger devient exécutable à cause 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 trames en attente de TouchLatency passe 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 rendre une troisième. C'est parce que nous avons déjà supprimé certaines images, donc 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 :
SurfaceFlinger verrouille d'abord l'ancien tampon en attente, ce qui entraîne la diminution du nombre de tampons en attente de 2 à 1.
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 , elles peuvent donc ne pas être incluses dans votre SoC.)
Ensuite, mdss_fb0 se réveille sur le CPU 0. mdss_fb0 est le thread noyau du pipeline d'affichage pour la sortie d'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, s'exécute brièvement, entre en veille ininterrompue, puis se réveille à nouveau.
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 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 :
Lorsque vous recherchez 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 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é avec SurfaceFlinger qui 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.
La figure 11 montre une image manquée à 15 598,29 ms. SurfaceFlinger s'est brièvement réveillé à l'intervalle vsync et s'est rendormi sans faire aucun travail, ce qui signifie que SurfaceFlinger a déterminé qu'il ne valait pas la peine d'essayer d'envoyer à nouveau une image à l'écran. Pourquoi?
Pour comprendre comment le pipeline est tombé en panne 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 s'endort immédiatement. Lors de l'affichage du nombre d'images en attente de TouchLatency, il y a deux images (un bon indice pour aider à comprendre ce qui se passe).
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 les deux normaux, il s'agit probablement d'un problème de pilote.
Étant donné que les points de 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 quand une image est affichée. Ces clôtures sont fournies dans le cadre de la catégorie de suivi de 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.
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 ne l'a pas été. Affichez l'image précédente et recherchez quoi que ce soit.
La figure 14 montre 14,482 ms par trame. Le segment cassé de deux images était de 33,6 ms, ce qui est à peu près ce à quoi nous nous attendions 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 du tout avec le tube d'affichage.
Enquêtez exactement où se termine cette clôture pour déterminer ce qui la contrôle.
Une file d'attente 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 être 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 (ce n'est pas un long délai de planification), mais c'est une file d'attente de travail et il se peut qu'il ne soit pas planifié avec précision.
Vérifiez l'image précédente pour déterminer si cela a contribué ; parfois, la gigue peut s'accumuler avec le temps et éventuellement entraîner un dépassement de délai.
La ligne exécutable sur le 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 est 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 (qui s'exécute en tant que thread SCHED_OTHER CFS) vers un SCHED_FIFO SCHED_FIFO dédié. Cette fonction nécessite des garanties de synchronisation que les files d'attente de travail ne peuvent pas (et ne sont pas destinées à) fournir.
Est-ce la raison du jank ? C'est difficile à dire avec certitude. En dehors des cas faciles à diagnostiquer, tels que les conflits 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 de trame? 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é à quel point le pipeline d'affichage est étroitement couplé, il est possible que la gigue autour des synchronisations de clôture ait entraîné une perte d'image.
Dans cet exemple, la solution consistait à convertir __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 de la secousse lors du test de la balle rebondissante. Les traces suivantes montrent des timings de clôture qui oscillent très près de 16,7 ms.