Traçage du noyau avec trace-cmd
trace-cmd est un utilitaire facile à utiliser et riche en fonctionnalités pour tracer les fonctions du noyau Linux.
Dans mon article précédent, j'ai expliqué comment utiliser ftrace pour tracer les fonctions du noyau. Utiliser ftrace en écrivant et en lisant à partir de fichiers peut devenir fastidieux, j'ai donc utilisé un wrapper autour pour exécuter des commandes avec des options pour activer et désactiver le traçage, définir des filtres, afficher la sortie, effacer la sortie, et plus encore.
La commande trace-cmd est un utilitaire qui vous aide à faire exactement cela. Dans cet article, j'utilise trace-cmd pour effectuer les mêmes tâches que celles effectuées dans mon article ftrace. Comme je reviens fréquemment à cet article, je vous recommande de le lire avant de lire celui-ci.
Installer trace-cmd
J'exécute les commandes de cet article en tant qu'utilisateur root.
Le mécanisme ftrace est intégré au noyau, et vous pouvez vérifier qu'il est activé avec :
# mount | grep tracefs
none on /sys/kernel/tracing type tracefs (rw,relatime,seclabel)Cependant, vous devez installer l'utilitaire trace-cmd manuellement.
# dnf install trace-cmd -yListe des traceurs disponibles
Lorsque vous utilisez ftrace, vous devez afficher le contenu d'un fichier pour voir quels traceurs sont disponibles. Mais avec trace-cmd, vous pouvez obtenir ces informations avec :
# trace-cmd list -t
hwlat blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup function nopActiver la fonction traceur
Dans mon article précédent, j'ai utilisé deux traceurs, et je ferai de même ici. Activez votre premier traceur, fonction, avec :
$ trace-cmd start -p function
plugin 'function'Afficher la sortie de trace
Une fois le traceur activé, vous pouvez afficher la sortie en utilisant les arguments show. Cela montre uniquement les 20 premières lignes pour garder l'exemple court (voir mon article précédent pour une explication du résultat) :
# trace-cmd show | head -20
## tracer: function
#
# entries-in-buffer/entries-written: 410142/3380032 #P:8
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
gdbus-2606 [004] ..s. 10520.538759: __msecs_to_jiffies <-rebalance_domains
gdbus-2606 [004] ..s. 10520.538760: load_balance <-rebalance_domains
gdbus-2606 [004] ..s. 10520.538761: idle_cpu <-load_balance
gdbus-2606 [004] ..s. 10520.538762: group_balance_cpu <-load_balance
gdbus-2606 [004] ..s. 10520.538762: find_busiest_group <-load_balance
gdbus-2606 [004] ..s. 10520.538763: update_group_capacity <-update_sd_lb_stats.constprop.0
gdbus-2606 [004] ..s. 10520.538763: __msecs_to_jiffies <-update_group_capacity
gdbus-2606 [004] ..s. 10520.538765: idle_cpu <-update_sd_lb_stats.constprop.0
gdbus-2606 [004] ..s. 10520.538766: __msecs_to_jiffies <-rebalance_domainsArrêtez le traçage et effacez le tampon
Le traçage continue de s'exécuter en arrière-plan et vous pouvez continuer à afficher le résultat à l'aide de show.
Pour arrêter le traçage, exécutez trace-cmd avec l'argument stop :
# trace-cmd stopPour vider le tampon, exécutez-le avec l'argument clear :
# trace-cmd clearActiver le traceur function_graph
Activez le deuxième traceur, function_graph, en exécutant :
# trace-cmd start -p function_graph
plugin 'function_graph'Encore une fois, affichez la sortie à l'aide de l'argument show. Comme prévu, la sortie est légèrement différente de la première sortie de trace. Cette fois, il inclut une chaîne d'appels de fonctions :
# trace-cmd show | head -20
## tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |
4) 0.079 us | } /* rcu_all_qs */
4) 0.327 us | } /* __cond_resched */
4) 0.081 us | rcu_read_unlock_strict();
4) | __cond_resched() {
4) 0.078 us | rcu_all_qs();
4) 0.243 us | }
4) 0.080 us | rcu_read_unlock_strict();
4) | __cond_resched() {
4) 0.078 us | rcu_all_qs();
4) 0.241 us | }
4) 0.080 us | rcu_read_unlock_strict();
4) | __cond_resched() {
4) 0.079 us | rcu_all_qs();
4) 0.235 us | }
4) 0.095 us | rcu_read_unlock_strict();
4) | __cond_resched() {Utilisez les commandes stop et clear pour arrêter le traçage et vider le tampon :
# trace-cmd stop
# trace-cmd clearAjustez le traçage pour augmenter la profondeur
Si vous souhaitez voir plus de profondeur dans les appels de fonction, vous pouvez modifier le traceur :
# trace-cmd start -p function_graph --max-graph-depth 5
plugin 'function_graph'Maintenant, lorsque vous comparez ce résultat avec ce que vous avez vu auparavant, vous devriez voir davantage d'appels de fonctions imbriqués :
# trace-cmd show | head -20
## tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |
6) | __fget_light() {
6) 0.804 us | __fget_files();
6) 2.708 us | }
6) 3.650 us | } /* __fdget */
6) 0.547 us | eventfd_poll();
6) 0.535 us | fput();
6) | __fdget() {
6) | __fget_light() {
6) 0.946 us | __fget_files();
6) 1.895 us | }
6) 2.849 us | }
6) | sock_poll() {
6) 0.651 us | unix_poll();
6) 1.905 us | }
6) 0.475 us | fput();
6) | __fdget() {Apprendre les fonctions disponibles à tracer
Si vous souhaitez tracer uniquement certaines fonctions et ignorer le reste, vous devez connaître les noms exacts des fonctions. Vous pouvez les obtenir avec l'argument list suivi de -f. Cet exemple recherche la fonction courante du noyau kmalloc, qui est utilisée pour allouer de la mémoire dans le noyau :
# trace-cmd list -f | grep kmalloc
bpf_map_kmalloc_node
mempool_kmalloc
__traceiter_kmalloc
__traceiter_kmalloc_node
kmalloc_slab
kmalloc_order
kmalloc_order_trace
kmalloc_large_node
__kmalloc
__kmalloc_track_caller
__kmalloc_node
__kmalloc_node_track_caller
[...]Voici le nombre total de fonctions disponibles sur mon système de test :
# trace-cmd list -f | wc -l
63165Fonctions liées au module de suivi du noyau
Vous pouvez également tracer les fonctions liées à un module de noyau spécifique. Imaginez que vous souhaitiez tracer les fonctions liées au module du noyau kvm. Assurez-vous que le module est chargé :
# lsmod | grep kvm_intel
kvm_intel 335872 0
kvm 987136 1 kvm_intelExécutez à nouveau trace-cmd avec l'argument list, et à partir du résultat, grep pour les lignes qui se terminent par ] . Cela filtrera les modules du noyau. Ensuite, grep le module du noyau kvm_intel, et vous devriez voir toutes les fonctions liées à ce module du noyau :
# trace-cmd list -f | grep ]$ | grep kvm_intel
vmx_can_emulate_instruction [kvm_intel]
vmx_update_emulated_instruction [kvm_intel]
vmx_setup_uret_msr [kvm_intel]
vmx_set_identity_map_addr [kvm_intel]
handle_machine_check [kvm_intel]
handle_triple_fault [kvm_intel]
vmx_patch_hypercall [kvm_intel]
[...]
vmx_dump_dtsel [kvm_intel]
vmx_dump_sel [kvm_intel]Fonctions spécifiques au trace
Maintenant que vous savez comment trouver des fonctions intéressantes, mettez ces connaissances en pratique avec un exemple. Comme dans l'article précédent, essayez de tracer les fonctions liées au système de fichiers. Le système de fichiers que j'avais sur mon système de test était ext4.
Cette procédure est légèrement différente ; au lieu de start, vous exécutez la commande avec l'argument record suivi du "modèle" des fonctions que vous souhaitez tracer. Vous devez également préciser le traceur souhaité ; dans ce cas, c'est function_graph. La commande continue d'enregistrer la trace jusqu'à ce que vous l'arrêtiez avec Ctrl+C. Ainsi, après quelques secondes, appuyez sur Ctrl+C pour arrêter le traçage :
# trace-cmd list -f | grep ^ext4_
# trace-cmd record -l ext4_* -p function_graph
plugin 'function_graph'
Hit Ctrl^C to stop recording
^C
CPU0 data recorded at offset=0x856000
8192 bytes in size
[...]Visualiser la trace enregistrée
Pour afficher la trace que vous avez enregistrée précédemment, exécutez la commande avec l'argument report. D'après le résultat, il est clair que le filtre a fonctionné et vous ne voyez que la trace de fonction liée à ext4 :
# trace-cmd report | head -20
[...]
cpus=8
trace-cmd-12697 [000] 11303.928103: funcgraph_entry: | ext4_show_options() {
trace-cmd-12697 [000] 11303.928104: funcgraph_entry: 0.187 us | ext4_get_dummy_policy();
trace-cmd-12697 [000] 11303.928105: funcgraph_exit: 1.583 us | }
trace-cmd-12697 [000] 11303.928122: funcgraph_entry: | ext4_create() {
trace-cmd-12697 [000] 11303.928122: funcgraph_entry: | ext4_alloc_inode() {
trace-cmd-12697 [000] 11303.928123: funcgraph_entry: 0.101 us | ext4_es_init_tree();
trace-cmd-12697 [000] 11303.928123: funcgraph_entry: 0.083 us | ext4_init_pending_tree();
trace-cmd-12697 [000] 11303.928123: funcgraph_entry: 0.141 us | ext4_fc_init_inode();
trace-cmd-12697 [000] 11303.928123: funcgraph_exit: 0.931 us | }
trace-cmd-12697 [000] 11303.928124: funcgraph_entry: 0.081 us | ext4_get_dummy_policy();
trace-cmd-12697 [000] 11303.928124: funcgraph_entry: 0.133 us | ext4_get_group_desc();
trace-cmd-12697 [000] 11303.928124: funcgraph_entry: 0.115 us | ext4_free_inodes_count();
trace-cmd-12697 [000] 11303.928124: funcgraph_entry: 0.114 us | ext4_get_group_desc();Tracer un PID spécifique
Supposons que vous souhaitiez tracer les fonctions liées à un identifiant persistant (PID) spécifique. Ouvrez un autre terminal et notez le PID du shell en cours d'exécution :
# echo $$
10885Exécutez à nouveau la commande record et transmettez le PID à l'aide de l'option -P. Cette fois, laissez le terminal fonctionner (c'est-à-dire n'appuyez pas encore sur Ctrl+C) :
# trace-cmd record -P 10885 -p function_graph
plugin 'function_graph'
Hit Ctrl^C to stop recordingExécuter une activité sur le shell
Revenez à l'autre terminal sur lequel vous aviez un shell exécuté avec un PID spécifique et exécutez n'importe quelle commande, par exemple ls pour lister les fichiers :
# ls
Temp-9b61f280-fdc1-4512-9211-5c60f764d702
tracker-extract-3-files.1000
v8-compile-cache-1000
[...]Revenez au terminal sur lequel vous avez activé le traçage et appuyez sur Ctrl+C pour arrêter le traçage :
# trace-cmd record -P 10885 -p function_graph
plugin 'function_graph'
Hit Ctrl^C to stop recording
^C
CPU1 data recorded at offset=0x856000
618496 bytes in size
[...]Dans la sortie de la trace, vous pouvez voir le PID et le shell Bash à gauche et les appels de fonction qui y sont associés à droite. Cela peut être très pratique pour affiner votre traçage :
# trace-cmd report | head -20
cpus=8
<idle>-0 [001] 11555.380581: funcgraph_entry: | switch_mm_irqs_off() {
<idle>-0 [001] 11555.380583: funcgraph_entry: 1.703 us | load_new_mm_cr3();
<idle>-0 [001] 11555.380586: funcgraph_entry: 0.493 us | switch_ldt();
<idle>-0 [001] 11555.380587: funcgraph_exit: 7.235 us | }
bash-10885 [001] 11555.380589: funcgraph_entry: 1.046 us | finish_task_switch.isra.0();
bash-10885 [001] 11555.380591: funcgraph_entry: | __fdget() {
bash-10885 [001] 11555.380592: funcgraph_entry: 2.036 us | __fget_light();
bash-10885 [001] 11555.380594: funcgraph_exit: 3.256 us | }
bash-10885 [001] 11555.380595: funcgraph_entry: | tty_poll() {
bash-10885 [001] 11555.380597: funcgraph_entry: | tty_ldisc_ref_wait() {
bash-10885 [001] 11555.380598: funcgraph_entry: | ldsem_down_read() {
bash-10885 [001] 11555.380598: funcgraph_entry: | __cond_resched() {Essaie
Ces brefs exemples montrent comment l'utilisation de trace-cmd au lieu du mécanisme ftrace sous-jacent est à la fois facile à utiliser et riche en fonctionnalités, dont beaucoup que je n'ai pas abordées ici. Pour en savoir plus et vous améliorer, consultez sa page de manuel et essayez ses autres commandes utiles.