Traçage du noyau avec trace-cmd | Opensource.com

Dans mon article précédent, j’ai expliqué comment utiliser ftrace pour tracer les fonctions du noyau. En utilisant ftrace en écrivant et en lisant des fichiers peut devenir fastidieux, j’ai donc utilisé un wrapper 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.

Le trace-cmd command 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 mécanisme 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

Lister les traceurs disponibles

Lors de l’utilisation 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 la fonction traceur

Dans mon article précédent, j’ai utilisé deux traceurs, et je vais faire de même 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 effacer le tampon :

# trace-cmd stop
# trace-cmd clear

Ajustez le traçage pour augmenter la profondeur

Si vous voulez 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() {

Apprendre les fonctions disponibles pour 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 le list argument suivi de -f. Cet exemple recherche la fonction noyau commune 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

Vous pouvez également tracer des fonctions liées à un module de noyau spécifique. Imaginez que vous voulez 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

Cours trace-cmd encore avec le 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 de 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]

Tracer des fonctions spécifiques

Maintenant que vous savez comment trouver les fonctions d’intérêt, 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 ; à la place 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. Alors 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 que 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 :

Run the record command again and pass the PID using the -P option. This time, let the terminal run (i.e., do not press Ctrl+C yet):

# 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 sur la gauche et les appels de fonction qui y sont liés sur la 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 utiliser trace-cmd au lieu du sous-jacent ftrace 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.