LeavaTailの日記

初心者がLinuxカーネルについて学習していく過程

trace-cmdでカーネルの関数のコールフローを取得する

はじめに

前回までで、kgdbでカーネルソースコードを読むための設定をした。

leavatail.hatenablog.com

leavatail.hatenablog.com

Linuxカーネルには、他にもトレース機能が提供されている。 ftraceはトレース機構の一つで、カーネルの実行中に実行されたさまざまな関数呼び出しに関連する情報を取得できる。

Ftrace is an internal tracer designed to help out developers and designers of systems to find what is going on inside the kernel. It can be used for debugging or analyzing latencies and performance issues that take place outside of user-space.

今回は、ftraceをユーザランドから使いやすくしたツールtrace-cmdを用いて、関数コールフローを追ってみる。

利用イメージは下記の通りとなっている。 ゲスト2で関数コールフローを採取し、同じネットワークにつながれているゲスト1へTCPでトレースデータtrace.datを取得する。

f:id:LeavaTail:20191118185807p:plain
関数コールフロー取得における利用イメージ

関数コールフローを採取するマシンと、トレースデータを取得するマシンを分けることで以下の利点がある。 *1

  • トレースデータを一つに集約することができる

ftraceとtrace-cmdの使い方など先駆者の方のリンクにまとめられているので、そちらを参照することをオススメする。

qiita.com

tasukuchan.hatenablog.com

qiita.com

yohgami.hateblo.jp

準備

内部ネットワークの構築

仮想マシン同士を同一ネットワークでつなげる (ゲスト1: 192.168.7.11、ゲスト2: 192.168.7.12)

# -*- mode: ruby -*-
# vi: set ft=ruby :

Vagrant.configure("2") do |config|
  config.vm.box = "ubuntu/bionic64"
  
  config.vm.define "debugger" do |c|
    c.vm.provider "virtualbox" do |vb|
      vb.memory = "4096"
      vb.cpus = 2
    end
    c.vm.network "private_network", ip: "192.168.7.11", virtualbox__intnet: "devnet"
  end

  config.vm.define "debuggee" do |c|
    c.vm.provider "virtualbox" do |vb|
      vb.memory = "4096"
      vb.cpus = 1
    end
    c.vm.network "private_network", ip: "192.168.7.12", virtualbox__intnet: "devnet"
  end

前回からの記事と同様に、ゲスト1をdebugger、ゲスト2をdebuggeeと呼ぶことにする。

ftraceの設定

trace-cmdを使用するためには、ftraceが使用できることが条件となっている。 ftraceが使える条件は以下の二つが設定されていることが重要である。

  • カーネルコンフィグレーションでftraceに対応している
  • debugfsをマウントしている

カーネルコンフィグレーションは以下の設定が必要である。(前回の仮想マシンではデフォルトで有効化になっているので変更不要)

CONFIG_FTRACE = y
CONFIG_FUNCTION_TRACER = y
CONFIG_FUNCTION_GRAPH_TRAC = y

debugfsのマウントも確認が必要である。

debuggee:~$ mount | grep debugfs
debugfs on /sys/kernel/debug type debugfs (rw,relatime)

trace-cmdのインストール

両方の仮想マシンにtrace-cmdをインストールする。

 debuggee:~$ sudo apt install trace-cmd
 debugger:~$ sudo apt install trace-cmd

実行

コマンドのトレースを取得する

1.ゲスト1(debugger)の11111ポートでトレースを待ち受ける (必要に応じてポート開放すること)

debugger:~$ sudo trace-cmd listen -p 11111

2.ゲスト2(debuggee)からlsコマンドを実行し、トレース結果をゲスト1(192.168.7.11)の11111ポートへ転送する

debuggee:~$ sudo trace-cmd record -N 192.168.7.11:11111 -p function_graph -F ls
  plugin 'function_graph'

3.トレースを出力したら、ゲスト1(debugger)のトレース待ち受け状態を^Cで解除する

Connected with 192.168.7.11:40234
cpus=1
pagesize=4096
CPU0 data recorded at offset=0x4a8000
    2039808 bytes in size
^C

debugger:~$

4.出力されたトレースデータtrace.192.168.7.11:40234.datをプレーンテキスト形式trace.listに出力する

debugger:~$ sudo trace-cmd report trace.192.168.7.12\:48144.dat > trace.list

5.出力結果の確認

debugger:~$ head -n 20 trace.list 
cpus=1
           <...>-2278  [000]  4757.532540: funcgraph_entry:        1.148 us   |  mutex_unlock();
           <...>-2278  [000]  4757.532541: funcgraph_entry:        0.274 us   |  __fsnotify_parent();
           <...>-2278  [000]  4757.532541: funcgraph_entry:        0.164 us   |  fsnotify();
           <...>-2278  [000]  4757.532542: funcgraph_entry:        0.114 us   |  __sb_end_write();
           <...>-2278  [000]  4757.532542: funcgraph_entry:                   |  __f_unlock_pos() {
           <...>-2278  [000]  4757.532542: funcgraph_entry:        0.122 us   |    mutex_unlock();
           <...>-2278  [000]  4757.532542: funcgraph_exit:         0.341 us   |  }
           <...>-2278  [000]  4757.532544: funcgraph_entry:                   |  __do_page_fault() {
           <...>-2278  [000]  4757.532544: funcgraph_entry:        0.118 us   |    down_read_trylock();
           <...>-2278  [000]  4757.532544: funcgraph_entry:                   |    _cond_resched() {
           <...>-2278  [000]  4757.532544: funcgraph_entry:        0.117 us   |      rcu_all_qs();
           <...>-2278  [000]  4757.532545: funcgraph_exit:         0.347 us   |    }
           <...>-2278  [000]  4757.532545: funcgraph_entry:                   |    find_vma() {
           <...>-2278  [000]  4757.532545: funcgraph_entry:        0.157 us   |      vmacache_find();
           <...>-2278  [000]  4757.532545: funcgraph_exit:         0.398 us   |    }
           <...>-2278  [000]  4757.532545: funcgraph_entry:                   |    handle_mm_fault() {
           <...>-2278  [000]  4757.532545: funcgraph_entry:        0.111 us   |      mem_cgroup_from_task();
           <...>-2278  [000]  4757.532546: funcgraph_entry:                   |      __handle_mm_fault() {
           <...>-2278  [000]  4757.532546: funcgraph_entry:        0.131 us   |        pmd_devmap_trans_unstable();
<snip>

プロセスのトレースを取得する

1.ゲスト1(debugger)の11111ポートでトレースを待ち受ける (必要に応じてポート開放すること)

debugger:~$ sudo trace-cmd listen -p 11111

2.ゲスト2(debuggee)において、トレース対象のプロセスのpidを確認する。(今回はjbd2を対象とする)

debuggee:~$ ps -e | grep jbd2
  330 ?        00:00:00 jbd2/sda1-8

3.ゲスト2(debuggee)からpidを指定し、トレース結果をゲスト1(192.168.7.11)の11111ポートへ転送する

debuggee:~$ sudo trace-cmd record -N 192.168.7.11:11111 -p function_graph -P 330 
  plugin 'function_graph'

4.プロセスが動作したことを確認したら、ゲスト2(debuggee)のトレース出力状態を^Cで解除する

^C

debuggee:~$

5.出力されたトレースデータtrace.192.168.7.11:48148.datをプレーンテキスト形式trace.listに出力する

Connected with 192.168.7.12:48148
cpus=1
pagesize=4096
CPU0 data recorded at offset=0x4ba000

debugger:~$ sudo trace-cmd report trace.192.168.7.12\:48148.dat > trace.list

6.出力結果の確認

debugger:~$ head -n 20 trace.list 
cpus=1
          <idle>-0     [000] 10069.427204: funcgraph_entry:      + 12.184 us  |  enter_lazy_tlb();
     jbd2/sda1-8-330   [000] 10069.427218: funcgraph_entry:                   |  finish_task_switch() {
     jbd2/sda1-8-330   [000] 10069.427225: funcgraph_entry:                   |    smp_irq_work_interrupt() {
     jbd2/sda1-8-330   [000] 10069.427226: funcgraph_entry:                   |      irq_enter() {
     jbd2/sda1-8-330   [000] 10069.427226: funcgraph_entry:                   |        rcu_irq_enter() {
     jbd2/sda1-8-330   [000] 10069.427227: funcgraph_entry:        0.638 us   |          rcu_nmi_enter();
     jbd2/sda1-8-330   [000] 10069.427228: funcgraph_exit:         1.779 us   |        }
     jbd2/sda1-8-330   [000] 10069.427229: funcgraph_exit:         2.952 us   |      }
     jbd2/sda1-8-330   [000] 10069.427235: funcgraph_entry:                   |      __wake_up() {
     jbd2/sda1-8-330   [000] 10069.427236: funcgraph_entry:                   |        __wake_up_common_lock() {
     jbd2/sda1-8-330   [000] 10069.427236: funcgraph_entry:        0.568 us   |          _raw_spin_lock_irqsave();
     jbd2/sda1-8-330   [000] 10069.427237: funcgraph_entry:        0.597 us   |          __wake_up_common();
     jbd2/sda1-8-330   [000] 10069.427239: funcgraph_entry:        0.568 us   |          __lock_text_start();
     jbd2/sda1-8-330   [000] 10069.427240: funcgraph_exit:         4.013 us   |        }
     jbd2/sda1-8-330   [000] 10069.427240: funcgraph_exit:         5.284 us   |      }
     jbd2/sda1-8-330   [000] 10069.427241: funcgraph_entry:                   |      __wake_up() {
     jbd2/sda1-8-330   [000] 10069.427241: funcgraph_entry:                   |        __wake_up_common_lock() {
     jbd2/sda1-8-330   [000] 10069.427242: funcgraph_entry:        0.550 us   |          _raw_spin_lock_irqsave();
     jbd2/sda1-8-330   [000] 10069.427243: funcgraph_entry:                   |          __wake_up_common() {
<snip>

イベントのトレースを取得する

1.ゲスト1(debugger)の11111ポートでトレースを待ち受ける (必要に応じてポート開放すること)

debugger:~$ sudo trace-cmd listen -p 11111

2.ゲスト2(debuggee)からイベントnetを指定し、トレース結果をゲスト1(192.168.7.11)の11111ポートへ転送する (指定できるイベントはtrace-cmd list -eで確認できる)

debugger:~$ sudo trace-cmd record -N 192.168.7.11:11111 -p function_graph -e net ping -c 1 192.168.7.11
  plugin 'function_graph'
PING 192.168.7.11 (192.168.7.11) 56(84) bytes of data.
64 bytes from 192.168.7.11: icmp_seq=1 ttl=64 time=0.176 ms

--- 192.168.7.11 ping statistics ---
1 packets transmitted, 1 received, 0% packet loss, time 0ms
rtt min/avg/max/mdev = 0.176/0.176/0.176/0.000 ms

3.トレースを出力したら、ゲスト1(debugger)のトレース待ち受け状態を^Cで解除する

Connected with 192.168.7.12:48150
cpus=1
pagesize=4096
CPU0 data recorded at offset=0x4be000
    1609728 bytes in size
^C

debugger:~$

4.出力されたトレースデータtrace.192.168.7.11:48150.datをプレーンテキスト形式trace.listに出力する

debugger:~$ sudo trace-cmd report trace.192.168.7.12\:48150.dat > trace.list

5.出力結果の確認

debugger:~$ head -n 20 trace.list 
cpus=1
           <...>-2746  [000] 10875.245946: funcgraph_entry:                   |  mutex_unlock() {
           <...>-2746  [000] 10875.245951: funcgraph_entry:                   |    smp_irq_work_interrupt() {
           <...>-2746  [000] 10875.245951: funcgraph_entry:                   |      irq_enter() {
           <...>-2746  [000] 10875.245952: funcgraph_entry:                   |        rcu_irq_enter() {
           <...>-2746  [000] 10875.245952: funcgraph_entry:        0.154 us   |          rcu_nmi_enter();
           <...>-2746  [000] 10875.245952: funcgraph_exit:         0.464 us   |        }
           <...>-2746  [000] 10875.245952: funcgraph_exit:         0.725 us   |      }
           <...>-2746  [000] 10875.245954: funcgraph_entry:                   |      __wake_up() {
           <...>-2746  [000] 10875.245954: funcgraph_entry:                   |        __wake_up_common_lock() {
           <...>-2746  [000] 10875.245954: funcgraph_entry:        0.121 us   |          _raw_spin_lock_irqsave();
           <...>-2746  [000] 10875.245954: funcgraph_entry:        0.116 us   |          __wake_up_common();
           <...>-2746  [000] 10875.245954: funcgraph_entry:        0.120 us   |          __lock_text_start();
           <...>-2746  [000] 10875.245954: funcgraph_exit:         0.835 us   |        }
           <...>-2746  [000] 10875.245955: funcgraph_exit:         1.076 us   |      }
           <...>-2746  [000] 10875.245955: funcgraph_entry:                   |      __wake_up() {
           <...>-2746  [000] 10875.245955: funcgraph_entry:                   |        __wake_up_common_lock() {
           <...>-2746  [000] 10875.245955: funcgraph_entry:        0.114 us   |          _raw_spin_lock_irqsave();
           <...>-2746  [000] 10875.245955: funcgraph_entry:        0.115 us   |          __wake_up_common();
           <...>-2746  [000] 10875.245955: funcgraph_entry:        0.122 us   |          __lock_text_start();
<snip>

おわりに

今回は、カーネルのコードリーディングに役立つftrace/trace-cmdの導入方法についてまとめた。 trace-cmdでカーネルの関数コールフローを取得することで、kgdbでブレークするポイントを特定したり、Linuxカーネルのコードを効率的に読むことができる。

次回は、コードリーディングに役立つツールkprobeの紹介をしたいと思う。

参考

*1:ただし、trace-cmdは採取するマシンと取得するマシンを分ける必要はない。