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