Linux Embedded

Le blog des technologies libres et embarquées

Introduction à Ftrace

Le but de l’outil Ftrace est d’analyser le comportement du système en mettant en place de l’instrumentation au niveau du noyau. Il s’agit donc d’une analyse des performances et non pas la correction d’un défaut de fonctionnement conduisant à l’arrêt du système qui lui nécessiterait l’utilisation d’un débogueur.
Un tel outil permet de tracer des évènements comme :

  • les appels systèmes;
  • les fonctions de traitement d’interruption;
  • les fonction d’ordonnancement;
  • les piles réseau

Notons également que l’enregistrement en temps réel de telles informations nécessite de stocker ou de transmettre une assez grande quantité de données et donc qu’une optimisation est nécessaire. De même, à l’instar des instruments de mesure physiques, les outils de trace doivent influer le moins possible sur les performances du système. Les différents outils de trace sont répertoriés dans le répertoire Documentation/trace des sources du noyau Linux.
L’outil Ftrace (littéralement Function Tracer) a été introduit dans le noyau 2.6.27 dans le but d’unifier les outils de trace du noyau. C’est donc un composant standard utilisable pour toutes les versions du noyau et pour toutes les architectures officiellement supportées.
Ftrace est capable de produire des informations concernant les latences, le traitement des interruptions, les changements de contexte (ou context switch). Il permet également de générer des graphes d’appels de fonctions. Notons que l’on peut également étendre les fonctionnalités de Ftrace en y ajoutant des greffons.
L’activation de Ftrace s’effectue dans le menu Kernel hacking de la configuration du noyau accessible par la commande make menuconfig (ou bien xconfig, gconfig). Pour cela, on doit activer l’option Tracers puis sélectionner les différents traceurs dans le sous-menu associé.
Une documentation d’utilisation très complète est disponible dans le fichier Documentation/trace/ftrace.txt. L’utilisation de Ftrace passe par les étapes suivantes :

  1. Sélectionner un traceur indiquant la fonctionnalité à tracer dans le noyau
  2. Définir un filtre pour limiter les traces produites (exemple: le nom de la fonction du pilote à tracer)
  3. Activer la trace en effectuant la commande :
    root# echo 1 > /proc/sys/kernel/ftrace_enabled
  4. Après enregistrement, désactiver la trace afin de limiter la taille des données par :
  5. root# echo 0 > /proc/sys/kernel/ftrace_enabled
  6. Exploiter les résultats

L’utilisation de Ftrace nécessite d’activer la fonctionnalité DebugFS qui est un système de fichiers dédié aux outils de mise au point. Tout comme /proc ou /sys, DebugFS permet de manipuler des données du noyau comme des fichiers classiques. Dans le cas de Ftrace, DebugFS permet de configurer les traces mais également d’obtenir les résultats dans un fichier virtuel. Notons que d’autres outils similaires comme LTTng utilisent également DebugFS.
Ce système de fichier est en général monté sur /debug ou bien /sys/kernel/debug. Si ce n’est pas fait automatiquement, on peut effectuer le montage par la commande :

root# mount -t debugfs nodev /sys/kernel/debug

On dispose alors du répertoire /sys/kernel/debug/tracing contenant entre-autres le fichier trace qui contient les résultats de l’instrumentation. Les autres principaux fichiers de ce répertoire sont donnés ci-après :

  • available_tracers contient les différents traceurs disponibles, soit nop, function, function_graph, …
  • current_tracer contient le traceur courant, donc une valeur de la liste précédente.
  • tracing_on permet d’activer/désactiver les traces en écrivant les valeur 1 ou 0.
  • available_events contient les évènements traçables comme sched_wakeup. Ces évènements correspondent à des points de trace (ou Tracepoints) statiques ajoutés au noyau Linux, voir Documentation/trace/events.txt.
  • set_ftrace_pid permet de tracer un processus donné par son PID.

Dans l’exemple qui suit nous allons tracer l’utilisation d’un pilote de test correspondant au module mydriver1.ko. Les fonctions open, release, read, write du pilote se limitent à une simple fonction printk. La configuration de l’instrumentation s’effectue simplement par les commandes décrites ci-après. Dans le cas présent nous limitons l’instrumentation aux fonctions du pilote testé en utilisant un filtre.

root# modprobe mydriver1.ko
root# cd /sys/kernel/debug/tracing
root# echo function > current_tracer
root# echo ‘mydriver1_*’ > set_trace_filter
root# cat set_strace_filter
mydriver1_release
mydriver1_open
mydriver1_write
mydriver1_read
root# echo 1 > tracing_on

On effectue ensuite un accès au pilote au travers du fichier spécial /dev/mydriver1, en effectuant les appels systèmes open, write, close par une simple commande echo puis on visualise les traces. L’affichage est assez clair mais précisons simplement que la colonne de droite correspond à la fonction appelante (exemple: chrdev_open).

root# echo salut > /dev/mydriver1

root# cat trace
# tracer: function
#
#       TASK-PID    CPU#    TIMESTAMP  FUNCTION
#          | |       |          |         |
bash-12960 [001] 3711754.199386: mydriver1_open <-chrdev_open
bash-12960 [001] 3711754.199413: mydriver1_write <-vfs_write
bash-12960 [001] 3711754.199419: mydriver1_release <-__fput 

Le traceur function_graph permet d’afficher le détail d’exécution d’une fonction en affichant un graphe détaillé reprenant l’allure d’un programme en C. Les fonctions sont délimitées par des accolades et pour chaque appel à une fonction on obtient le temps d’exécution. Si la durée d’exécution est supérieure à 10 µs, le caractère ‘+’ est affiché et si elle est supérieure à 100 µs, le caractère ‘!’ est affiché. Pour activer le graphe on doit effectuer la commande :

root# echo function_graph > current_tracer

On peut alors visualiser le résultat dans le fichier trace :

# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |
1)   1.015 us    |        _spin_lock_irqsave();
1)   0.476 us    |        internal_add_timer();
1)   0.423 us    |        wake_up_idle_cpu();
1)   0.461 us    |        _spin_unlock_irqrestore();
1)   4.770 us    |      }
1)   5.725 us    |    }
1)   0.450 us    |    mutex_unlock();
1) + 24.243 us   |  }   ← délai > 10 µs
1)   0.483 us    |  _spin_lock_irq();
1)   0.517 us    |  _spin_unlock_irq();
1)               |  prepare_to_wait() {
1)   0.468 us    |    _spin_lock_irqsave();
1)   0.502 us    |    _spin_unlock_irqrestore();
1)   2.411 us    |  }
1)   0.449 us    |  kthread_should_stop();
1)               |  schedule() {

La fonction trace_printk est un autre point intéressant de Ftrace car elle permet de remplacer avantageusement la célèbre – et intrusive – fonction printk. Contrairement à printk, trace_printk est utilisable dans tous les contextes (ordonnanceur, interruption, …) car elle consomme quelques µs au lieu des quelques ms de printk. L’appel à trace_printk apparaitra dans le fichier trace comme le montre l’exemple qui suit.
Le code source ajouté est donné ci-après :

trace_printk("read foo %d out of bar %p\n", bar->foo, bar);

Dans le cas du traceur function, l’affichage dans le fichier trace sera le suivant :

#      TASK-PID    CPU#    TIMESTAMP  FUNCTION
#        | |       |          |         |
<...>-10690 [003] 17279.332920: : read foo 10 out of bar ffff880013a5bef8

Dans le cas du traceur function_graph, le résultat sera le suivant :

3)               |    do_one_initcall() {
3)               |      /* read foo 10 out of bar ffff88001191bef8 */
3)   4.221 us    |    }

La fonctionnalité trace_marker permet de provoquer des traces depuis l’espace utilisateur. Si nous utilisons la commande :

root# echo hello world > trace_marker

Le résultat sera visible dans le fichier trace :

bash-6842  [000] 2245230.244514: 0: hello world

De même, on peut insérer le code qui suit dans un programme en espace utilisateur :

req.tv_sec = 0;
req.tv_nsec = 1000;
write(marker_fd, "before nano\n", 12);
nanosleep(&req, NULL);
write(marker_fd, "after nano\n", 11);
write(trace_fd, "0", 1);

L’utilisation de function_graph donnera le résultat suivant :

# CPU  DURATION             FUNCTION CALLS
#
0)            |      /* before nano */
0)            |      kfree() {
0)   0.475 us |        __phys_addr();
0)   2.062 us |      }
0)   0.608 us |      inotify_inode_queue_event();
...
0)            |      /* after nano */
0)            |      kfree() {
0)   0.486 us |        __phys_addr();

Il est bien entendu possible de démarrer/arrêter l’enregistrement depuis un programme en espace utilisateur, par exemple sur une condition d’erreur.

int  fd, trace_fd;
char one = '1';

/* Open trace activation file */
if ((trace_fd = open("/sys/kernel/debug/tracing/tracing_on", O_WRONLY)) == -1)
{
perror("Can't open tracing file.");
exit(-3);
}
else
/* Activate tracing */
if (write(trace_fd, &one, 1) < 0)
{
perror("Can't write on tracing file.");
exit(-4);
}

Debugging the kernel using Ftrace – part 1
Debugging the kernel using Ftrace – part 2
Secrets of the Ftrace function tracer
trace-cmd – command line reader for ftrace
Introduction à Ftrace par Ken Werner
Installing and Using Ftrace
ftrace and perf support for I-pipe & Xenomai

Laisser un commentaire

Votre adresse de messagerie ne sera pas publiée. Les champs obligatoires sont indiqués avec *