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

  • FrançaisFrançais



  • 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.

    Source

    N'oubliez pas de voter pour cet article !
    1 Star2 Stars3 Stars4 Stars5 Stars (No Ratings Yet)
    Loading...

    Laisser un commentaire

    Votre adresse e-mail ne sera pas publiée.