Utiliser ftrace

ftrace est un outil de débogage qui permet de comprendre ce qui se passe à l'intérieur du noyau Linux. Les sections suivantes décrivent les fonctionnalités de base de ftrace : ftrace utilisation avec atrace (qui capture les événements du noyau) et ftrace dynamique.

Pour en savoir plus sur la fonctionnalité ftrace avancée qui n'est pas disponible sur Systrace, consultez la documentation sur ftrace <kernel tree>/Documentation/trace/ftrace.txt

Capturer les événements du noyau avec atrace

atrace (frameworks/native/cmds/atrace) utilise ftrace pour capturer les événements du noyau. À son tour, systrace.py (ou run_systrace.py dans les versions ultérieures de Catapult) utilise adb. pour exécuter une trace sur l'appareil. atrace effectue les opérations suivantes:

  • Configure le traçage du mode utilisateur en définissant une propriété. (debug.atrace.tags.enableflags).
  • Active la fonctionnalité ftrace souhaitée en écrivant dans le bon fichier ftrace sysfs nœuds. Toutefois, comme ftrace prend en charge d'autres fonctionnalités, vous pouvez définir certains nœuds sysfs vous-même, puis utilisez atrace.

À l'exception du traçage au démarrage, utilisez atrace pour définir le sur la valeur appropriée. La propriété est un masque de bits, moyen de déterminer les valeurs correctes, autrement que de regarder l'en-tête approprié (qui peuvent varier d'une version d'Android à l'autre).

Activer les événements ftrace

Les nœuds ftrace sysfs se trouvent dans /sys/kernel/tracing et trace événements sont divisés en catégories dans /sys/kernel/tracing/events.

Pour activer les événements par catégorie, utilisez:

echo 1 > /sys/kernel/tracing/events/irq/enable

Pour activer les événements par événement, utilisez:

echo 1 > /sys/kernel/tracing/events/sched/sched_wakeup/enable

Si des événements supplémentaires ont été activés en écrivant sur des nœuds sysfs, ils ne pas être réinitialisés par atrace. Un modèle courant pour la mise en service des appareils Qualcomm consiste à activer kgsl (GPU) et mdss (pipeline d'affichage), puis utilisez atrace ou systrace:

adb shell "echo 1 > /sys/kernel/tracing/events/mdss/enable"
adb shell "echo 1 > /sys/kernel/tracing/events/kgsl/enable"
./systrace.py sched freq idle am wm gfx view binder_driver irq workq ss sync -t 10 -b 96000 -o full_trace.html

Vous pouvez aussi utiliser ftrace sans atrace ni Systrace, utile lorsque vous avez besoin de traces uniquement du noyau (ou si vous avez pris le temps d'écrire la propriété de traçage manuel du mode utilisateur). Pour n'exécuter que ftrace:

  1. Définissez la taille de la mémoire tampon sur une valeur suffisante pour votre trace:
    echo 96000 > /sys/kernel/tracing/buffer_size_kb
    
  2. Activez le traçage:
    echo 1 > /sys/kernel/tracing/tracing_on
    
  3. Exécutez votre test, puis désactivez le traçage:
    echo 0 > /sys/kernel/tracing/tracing_on
    
  4. Videz la trace:
    cat /sys/kernel/tracing/trace > /data/local/tmp/trace_output
    

trace_output donne la trace au format texte. Pour les visualiser à l'aide de Catapulte Catapulte dépôt depuis GitHub et exécutez trace2html:

catapult/tracing/bin/trace2html ~/path/to/trace_file

Par défaut, trace_file.html est écrit dans le même fichier .

Corréler des événements

Il est souvent utile d'examiner la visualisation Catapulte et la fonction ftrace consigner simultanément ; par exemple, certains événements ftrace (en particulier ceux spécifiques au fournisseur 1) ne sont pas visualisées par Catapult. Cependant, les codes temporels de Catapult sont par rapport au premier événement de la trace ou à un horodatage spécifique vide par atrace, tandis que les horodatages ftrace bruts sont basés sur une valeur source d'horloge absolue dans le noyau Linux.

Pour rechercher un événement ftrace donné à partir d'un événement Catapulte:

  1. Ouvrez le journal ftrace brut. Dans les versions récentes de Systrace, les traces sont compressés par défaut: <ph type="x-smartling-placeholder">
      </ph>
    • Si vous avez capturé votre trace Systrace avec --no-compress, il se trouve dans le fichier html dans la section commençant par DÉBUT TRACE.
    • Si ce n'est pas le cas, exécutez html2trace à partir de Catapulte tree (tracing/bin/html2trace) pour décompresser la trace.
  2. Trouvez le code temporel relatif dans la visualisation Catapult.
  3. Trouver une ligne au début de la trace contenant tracing_mark_sync Exemple :
    <5134>-5134  (-----) [003] ...1    68.104349: tracing_mark_write: trace_event_clock_sync: parent_ts=68.104286
    

    Si cette ligne n'existe pas (ou si vous avez utilisé ftrace sans atrace), alors les codes temporels seront relatifs à partir du premier événement du journal ftrace.
    1. Ajoutez le code temporel relatif (en millisecondes) à la valeur de parent_ts (en secondes).
    2. Recherchez le nouvel horodatage.

Ces étapes devraient vous placer à l'événement (ou au moins très près).

Utiliser ftrace dynamique

Lorsque Systrace et ftrace standard sont insuffisants, il y en a une dernière recours disponible: dynamique ftrace. Une trace ftrace dynamique implique une réécriture du code du noyau après le démarrage. Il n'est donc pas disponible en production pour des raisons de sécurité. Cependant, tous les bugs de performances difficiles 2015 et 2016 ont finalement été causés par l'utilisation de la fonction ftrace dynamique. C'est particulièrement est très utile pour déboguer les périodes de veille sans interruption, car vous pouvez obtenir une trace de la pile dans le noyau chaque fois que vous appuyez sur la fonction, ce qui déclenche une veille ininterrompue. Vous pouvez également déboguer des sections en désactivant les interruptions et les préemptions, ce qui peut être très utile pour prouver des problèmes.

Pour activer la ftrace dynamique, modifiez le fichier defconfig du noyau:

  1. Supprimez CONFIG_STRICT_MEMORY_RWX (s'il est présent). Si vous utilisez la version 3.18 ou plus récent et arm64, il n'est pas là.
  2. Ajoutez les éléments suivants: CONFIG_DYNAMIC_FTRACE=y, CONFIG_FUNCTION_TRACER=y, CONFIG_IQSOFF_TRACER=y, CONFIG_FUNCTION_PROFILER=y et CONFIG_PREEMPT_TRACER=y
  3. Recompilez et démarrez le nouveau noyau.
  4. Exécutez la commande suivante pour vérifier si des traceurs sont disponibles:
    cat /sys/kernel/tracing/available_tracers
    
  5. Vérifiez que la commande renvoie function, irqsoff, preemptoff et preemptirqsoff.
  6. Exécutez la commande suivante pour vous assurer que ftrace dynamique fonctionne:
    cat /sys/kernel/tracing/available_filter_functions | grep <a function you care about>
    

Après avoir suivi ces étapes, vous disposez de ftrace dynamique, le profileur de fonctions, le profileur irqsoff et le profileur préempte sont disponibles. Nous vivons Nous vous recommandons de lire la documentation de ftrace sur ces sujets avant de l'utiliser car ils sont puissants mais complexes. « irqsoff » et préempte sont principalement Utile pour confirmer que les conducteurs risquent de subir des interruptions ou de la préemption désactivée pendant trop longtemps.

Le Profileur de fonctions est la meilleure option pour les problèmes de performances. Il est souvent utilisé pour savoir où une fonction est appelée.

Dans ce numéro, si vous utilisez un Pixel XL pour prendre une photo HDR+, la rotation du viseur entraînait des à-coups à chaque fois. Nous avons utilisé le profileur de fonctions pour pour résoudre le problème en moins d'une heure. Pour suivre cet exemple, téléchargez le fichier ZIP contenant les traces (qui contient également inclut d'autres traces mentionnées dans cette section), décompressez le fichier et ouvrez trace_30898724.html dans votre navigateur.

La trace montre que plusieurs threads du processus cameraserver sont bloqués dans veille ininterrompue sur ion_client_destroy. Cela coûte cher mais ne doit être appelé que très rarement, car les clients ion doivent englobent de nombreuses allocations. Au départ, c'était le code hexagone Halide, qui était effectivement l'un des coupables (il a créé un nouveau client pour chaque l'allocation d'ions et détruit ce client lorsque l'allocation a été libérée, ce qui était beaucoup trop chère). Passer à un seul client ion pour tous les appareils Hexagon a amélioré la situation, mais l'à-coup n'a pas été résolu.

À ce stade, nous devons savoir qui appelle ion_client_destroy. Il est donc temps d'utiliser le profileur de fonctions:

  1. Comme les fonctions sont parfois renommées par le compilateur, vérifiez ion_client_destroy y a recours à l'aide de la commande suivante:
    cat /sys/kernel/tracing/available_filter_functions | grep ion_client_destroy
    
  2. Après avoir vérifié qu'il s'y trouve, utilisez-le comme filtre ftrace:
    echo ion_client_destroy > /sys/kernel/tracing/set_ftrace_filter
    
  3. Activez le profileur de fonctions:
    echo function > /sys/kernel/tracing/current_tracer
    
  4. Activez les traces de la pile chaque fois qu'une fonction de filtre est appelée:
    echo func_stack_trace > /sys/kernel/tracing/trace_options
    
  5. Augmentez la taille de la mémoire tampon:
    echo 64000 > /sys/kernel/tracing/buffer_size_kb
    
  6. Activez le traçage:
    echo 1 > /sys/kernel/tracing/trace_on
    
  7. Exécutez le test et obtenez la trace:
    cat /sys/kernel/tracing/trace > /data/local/tmp/trace
    
  8. Affichez la trace pour voir un grand nombre de traces de pile:
        cameraserver-643   [003] ...1    94.192991: ion_client_destroy <-ion_release
        cameraserver-643   [003] ...1    94.192997: <stack trace>
     => ftrace_ops_no_ops
     => ftrace_graph_call
     => ion_client_destroy
     => ion_release
     => __fput
     => ____fput
     => task_work_run
     => do_notify_resume
     => work_pending
     

L'inspection du pilote d'ion nous permet de voir que ion_client_destroy fait l'objet d'un spam par la fermeture d'une fonction de l'espace utilisateur un fd à /dev/ion, et non un pilote de noyau aléatoire. En effectuant une recherche Codebase Android pour \"/dev/ion\", nous avons trouvé plusieurs pilotes de fournisseurs fait la même chose que le pilote hexagone et /dev/ion (création et destruction d'un client ion) chaque fois qu'elles ont besoin d'une nouvelle allocation d'ions. En les remplaçant par utiliser un seul client ion pendant la durée de vie du processus. Le bug a été corrigé.


Si les données du profileur de fonctions ne sont pas assez spécifiques, vous pouvez combiner ftrace tracepoints avec le profileur de fonctions. Les événements ftrace peuvent être activés exactement comme d'habitude, et elles seront entrelacées avec votre trace. Cela s'avère très utile s'il y a de temps en temps une longue période de sommeil sans interruption fonction que vous souhaitez déboguer: définissez le filtre ftrace sur la fonction de votre choix, activer les tracepoints, effectuer une trace. Vous pouvez analyser la trace obtenue avec trace2html, recherchez l'événement qui vous intéresse, puis obtenez les traces de la pile à proximité dans la trace brute.

Utiliser les statistiques verrouillées

Parfois, ftrace ne suffit pas et vous devez vraiment déboguer ce qui semble être des conflits de verrouillage du noyau. Il existe une autre option de noyau qui vaut la peine d’essayer: CONFIG_LOCK_STAT Ceci est un dernier recours, car il est extrêmement est difficile à utiliser sur les appareils Android, car la taille au-delà de ce que la plupart des périphériques peuvent gérer.

Toutefois, Lockstat utilise le code le verrouillage de l'infrastructure, ce qui est utile pour de nombreuses autres applications. Tout le monde sur l'affichage de l'appareil devrait trouver un moyen de faire fonctionner cette option. sur chaque appareil, car vous penserez à un moment "Si seulement je pouvais activer LOCK_STAT, je pourrais confirmer ou réfuter cela en cinq minutes au lieu de cinq jours. »

Dans ce problème, le thread SCHED_FIFO s'est bloqué lorsque tous les cœurs étaient au maximum avec des threads non-SCHED_FIFO. Nous avions des traces montrant un verrouillage important conflit sur une fd dans les applications de RV, mais nous n'avons pas pu identifier facilement la fd en cours d'utilisation. Pour suivre l'exemple, téléchargez le fichier ZIP fichier de traces (qui inclut également d'autres traces mentionnées dans ce fichier ), décompressez le fichier et ouvrez le fichier trace_30905547.html dans votre navigateur.

Nous avons supposé que ftrace lui-même était à l'origine des conflits de verrouillage, lorsqu'un un thread à faible priorité commence à écrire dans le canal ftrace, préemptive avant de pouvoir déverrouiller la serrure. Dans le pire des scénarios, a été exacerbé par la combinaison de threads de très faible priorité qui écrivent dans Marqueur ftrace, ainsi que des threads de priorité supérieure qui tournent sur les CPU pour pour simuler un appareil entièrement chargé.

Comme nous n'avons pas pu utiliser ftrace pour le débogage, LOCK_STAT fonctionne puis désactivé tout autre traçage à partir de l'application. Les résultats ont montré que le verrou le conflit provenait en fait de ftrace, car aucun élément ne s'est produit dans la trace du verrou lorsque ftrace n'était pas en cours d'exécution.


Si vous pouvez démarrer un noyau avec l'option de configuration, le traçage de verrouillage est similaire à ftrace:

  1. Activez le traçage:
    echo 1 > /proc/sys/kernel/lock_stat
    
  2. Exécutez votre test.
  3. Désactivez le traçage:
    echo 0 > /proc/sys/kernel/lock_stat
    
  4. Videz votre trace:
    cat /proc/lock_stat > /data/local/tmp/lock_stat
    

Pour obtenir de l'aide sur l'interprétation du résultat, consultez la documentation de Lockstat. à l'adresse <kernel>/Documentation/locking/lockstat.txt.

Utiliser les points de trace des fournisseurs

Utilisez d'abord des tracepoints en amont, mais vous devrez parfois utiliser des tracepoints du fournisseur:

  { "gfx",        "Graphics",         ATRACE_TAG_GRAPHICS, {
        { OPT,      "events/mdss/enable" },
        { OPT,      "events/sde/enable" },
        { OPT,      "events/mali_systrace/enable" },
    } },

Les points de trace sont extensibles par le service HAL, ce qui vous permet d'ajouter une trace spécifique à l'appareil ou catégories. Les points de trace sont intégrés à Perfetto, atrace/systrace et au système sur l'appareil application de traçage.

Les API permettant d'implémenter des points de trace/catégories sont les suivantes:

  • listCategories()generates (catégories<TracingCategory>);
  • enableCategories(vec<string>categories) génère (statut de statut) ;
  • désactiverAllCategories() génère (État d'état);
Pour en savoir plus, reportez-vous à la définition de HAL et à l'implémentation par défaut dans AOSP: