Traçage du noyau avec trace-cmd

Dans mon article précédent, j'expliquais comment utiliser ftrace tracer les fonctions du noyau. Utilisation de ftrace en écrivant et en lisant des 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, etc.

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 j'ai faites dans mon ftrace article. Comme je me réfère 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 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 le trace-cmd utilitaire manuellement.

# dnf install trace-cmd -y

Liste des traceurs disponibles

Lors de l'utilisation de 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 nop

Activer le traceur de fonction

Dans mon article précédent, j'ai utilisé deux traceurs, et je vais faire la même chose ici. Activez votre premier traceur, function , 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 le show arguments. Cela ne montre que les 20 premières lignes pour garder l'exemple court (voir mon article précédent pour une explication de la sortie) :

# 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_domains

Arrêter le traçage et effacer le tampon

Le traçage continue de s'exécuter en arrière-plan et vous pouvez continuer à afficher la sortie en utilisant show .

Pour arrêter le traçage, exécutez trace-cmd avec le stop argument :

# trace-cmd stop

Pour effacer le tampon, exécutez-le avec le clear argument :

# trace-cmd clear

Activer le traceur function_graph

Activer le deuxième traceur, function_graph , en exécutant :

# trace-cmd start -p function_graph

  plugin 'function_graph'

Encore une fois, affichez la sortie en utilisant le show argument. Comme prévu, la sortie est légèrement différente de la première sortie de trace. Cette fois, il comprend un function calls chaîne :

# 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 le stop et clear commandes pour arrêter le traçage et vider le tampon :

# trace-cmd stop

# trace-cmd clear

Ajuster 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 cette sortie avec ce que vous avez vu auparavant, vous devriez voir plus d'appels de fonction 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() {

Apprenez les fonctions disponibles à tracer

Si vous souhaitez suivre uniquement certaines fonctions et ignorer le reste, vous devez connaître les noms exacts des fonctions. Vous pouvez les obtenir avec la list argument suivi de -f . Cet exemple recherche la fonction commune du noyau kmalloc , qui est utilisé 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

63165

Tracer les fonctions liées au module du noyau

Vous pouvez également suivre les fonctions liées à un module de noyau spécifique. Imaginez que vous vouliez tracer kvm fonctions liées au module du noyau. Assurez-vous que le module est chargé :

# lsmod  | grep kvm_intel

kvm_intel             335872  0

kvm                   987136  1 kvm_intel

Exécutez trace-cmd à nouveau avec la list argument, et à partir de la sortie, grep pour les lignes qui se terminent par ] . Cela filtrera les modules du noyau. Puis grep le module 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]

Plus de ressources Linux

• Aide-mémoire des commandes Linux
• Aide-mémoire des commandes Linux avancées
• Cours en ligne gratuit :Présentation technique de RHEL
• Aide-mémoire sur le réseau Linux
• Aide-mémoire SELinux
• Aide-mémoire sur les commandes courantes de Linux
• Que sont les conteneurs Linux ?
• Nos derniers articles Linux

Fonctions spécifiques au suivi

Maintenant que vous savez comment trouver les fonctions qui vous intéressent, 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 le record argument suivi du "modèle" des fonctions que vous souhaitez tracer. Vous devez également spécifier le traceur que vous souhaitez; dans ce cas, c'est function_graph . La commande continue d'enregistrer la trace jusqu'à ce que vous l'arrêtiez avec Ctrl+C . Donc, 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

[...]

Afficher la trace enregistrée

Pour afficher la trace que vous avez enregistrée précédemment, exécutez la commande avec le report argument. D'après la sortie, il est clair que le filtre a fonctionné et vous ne voyez que la trace de la 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 des 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 $$

10885

Exécutez l'record commande à nouveau et passez le PID en utilisant le -P option. Cette fois, laissez le terminal s'exécuter (c'est-à-dire, n'appuyez pas sur Ctrl+C encore):

# trace-cmd record -P 10885 -p function_graph

  plugin 'function_graph'

Hit Ctrl^C to stop recording

Exécuter une activité sur le shell

Revenez à l'autre terminal où vous aviez un shell en cours d'exécution 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 où 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 lui 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() {

Essayez-le

Ces brefs exemples montrent comment utiliser trace-cmd au lieu du ftrace sous-jacent mécanisme 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.