Logo

Ftrace を理解する

詳解システムパフォーマンスの 14 章「Ftrace」の内容を実際に手元で動かし、理解する

Last Modified: 2025/03/31


Ftrace とは

Ftrace（Function Tracer）は、Linux カーネルに組み込まれたトレーシングシステムで、カーネルの動作を詳細に調査できます。 Ftrace は、プロファイラ と トレーサー というものを持ち、 /sys/kernel/debug/tracing 以下のファイルシステムインターフェースを通じて操作できます。

tracefs は元々 debugfs の一部でしたが、分離し、tracing サブディレクトリにマウントされる。

> mount -t debugfs,tracefs
tracefs on /sys/kernel/tracing type tracefs (rw,nosuid,nodev,noexec,relatime,seclabel)
debugfs on /sys/kernel/debug type debugfs (rw,nosuid,nodev,noexec,relatime,seclabel)

Ftrace プロファイラ

カーネル関数呼び出しの統計を提供する機能。 これを使うのには CONFIG_FUNCTION_PROFILER=y オプションが有効になっている必要がある。(自分は fedora 42 で実行)

> cat /boot/config-$(uname -r) | grep CONFIG_FUNCTION_PROFILER
CONFIG_FUNCTION_PROFILER=y

実際に使ってみる 今回は vfs から始まる関数の呼び出しをまとめてみる。

> pwd
/sys/kernel/debug/tracing
> echo 'vfs*' > set_ftrace_filter
> echo 1 > function_profile_enabled; sleep 3; echo 0 > function_profile_enabled
> head trace_stat/function*
==> trace_stat/function0 <==
  Function                               Hit    Time            Avg             s^2
  --------                               ---    ----            ---             ---
  vfs_write                                2    59.580 us       29.790 us       1774.888 us
  vfs_statx                                5    55.337 us       11.067 us       131.106 us
  vfs_open                                 4    15.005 us       3.751 us        3.519 us
  vfs_getattr_nosec                        5    1.771 us        0.354 us        0.046 us
  vfs_fstat                                1    0.547 us        0.547 us        0.000 us
  vfs_statx_path.part.0                    4    0.291 us        0.072 us        0.000 us

==> trace_stat/function1 <==
  Function                               Hit    Time            Avg             s^2
  --------                               ---    ----            ---             ---
  vfs_read                               117    833.234 us      7.121 us        2071.507 us
  vfs_open                                71    140.215 us      1.974 us        41.004 us
  vfs_fstat                               80    39.467 us       0.493 us        0.099 us
  vfs_getattr_nosec                       80    20.147 us       0.251 us        0.031 us
  vfs_write                                1    5.275 us        5.275 us        0.000 us

なお、function0, function1 はそれぞれ CPU 0, 1 の結果。

他にも kprobe を使った kprobe プロファイラ、uprobe を使った uprobe がある。

Ftrace トレーサー

ここではカーネル関数呼び出しの詳細を取得することができます。 なお、インストルメンテーション方法は前節のプロファイラと同じであり、表示方法が異なるという認識。

使い方としては以下の流れ

  1. set_ftrace_filter にトレースする関数を登録 (使用可能な関数は available_filter_function で確認可能)
  2. tracing_on=1 に設定かつ、current_tracer=function に設定
  3. 出力結果を trace または trace_pipe から確認

実際にやってみる。

> cat tracing_on
1
> echo 'vfs*' > set_ftrace_filter
> echo function > current_tracer; sleep 5; head -n 20 trace
# tracer: function
#
# entries-in-buffer/entries-written: 102459/198303   #P:2
#
#                                _-----=> irqs-off/BH-disabled
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| / _-=> migrate-disable
#                              |||| /     delay
#           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
#              | |         |   |||||     |         |
             cat-31455   [001] ..... 17964.047380: vfs_read <-ksys_read
             cat-31455   [001] ..... 17964.047389: vfs_write <-ksys_write
             cat-31455   [001] ..... 17964.047394: vfs_read <-ksys_read
             cat-31455   [001] ..... 17964.047403: vfs_write <-ksys_write
             cat-31455   [001] ..... 17964.047409: vfs_read <-ksys_read
             cat-31455   [001] ..... 17964.047415: vfs_write <-ksys_write
             cat-31455   [001] ..... 17964.047419: vfs_read <-ksys_read
             cat-31455   [001] ..... 17964.047425: vfs_write <-ksys_write
> echo nop > current_tracer
> echo > set_ftrace_filter

出力を見ればわかりますが、PID や CPU ID, タイムスタンプ、どの関数から何が呼ばれたかが確認できます。

available_filter_function の関数からイベントを取得したが、静的インストルメンテーションからもイベントを取得しトレースできる。

> echo 0 > events/net/netif_rx/enable
> echo 1 > events/net/netif_receive_skb/enable
> head -n 20 trace
# tracer: nop
#
# entries-in-buffer/entries-written: 20/20   #P:2
#
#                                _-----=> irqs-off/BH-disabled
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| / _-=> migrate-disable
#                              |||| /     delay
#           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
#              | |         |   |||||     |         |
             zsh-39829   [000] ..s1. 35522.449865: netif_receive_skb: dev=ens5 skbaddr=00000000107ccaba len=52
             zsh-39829   [000] ..s1. 35522.449870: netif_receive_skb: dev=ens5 skbaddr=00000000f64f5642 len=52
          <idle>-0       [000] ..s1. 35522.450448: netif_receive_skb: dev=ens5 skbaddr=00000000396063ad len=52
          <idle>-0       [000] ..s1. 35522.455066: netif_receive_skb: dev=ens5 skbaddr=00000000d38978cf len=52
          <idle>-0       [000] ..s1. 35522.504437: netif_receive_skb: dev=ens5 skbaddr=00000000d5625531 len=52
          <idle>-0       [000] ..s1. 35522.508387: netif_receive_skb: dev=ens5 skbaddr=000000003bbb61a5 len=52
          <idle>-0       [000] ..s1. 35522.951339: netif_receive_skb: dev=ens5 skbaddr=000000004a7769ab len=104
          <idle>-0       [000] ..s1. 35522.961092: netif_receive_skb: dev=ens5 skbaddr=000000004a7769ab len=52
> echo 0 > events/net/netif_receive_skb/enable

kprobe を使ってもトレースができます。 kprobe はカーネル内のほぼすべての場所にフックできます。(NOKPROBE_SYMBOLマクロがあるとそのアドレス範囲には kprobe が使えない) フック可能な場所は /proc/kallsyms で確認可能。

> echo 'p:takloose  do_nanosleep' >> kprobe_events
> cat kprobe_events
p:kprobes/takloose do_nanosleep
> echo 1 > events/kprobes/takloose/enable
> cat trace
# tracer: nop
#
# entries-in-buffer/entries-written: 86/86   #P:2
#
#                                _-----=> irqs-off/BH-disabled
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| / _-=> migrate-disable
#                              |||| /     delay
#           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
#              | |         |   |||||     |         |
             zsh-39829   [000] ..s1. 35522.449865: netif_receive_skb: dev=ens5 skbaddr=00000000107ccaba len=52
             zsh-39829   [000] ..s1. 35522.449870: netif_receive_skb: dev=ens5 skbaddr=00000000f64f5642 len=52
          <idle>-0       [000] ..s1. 35522.450448: netif_receive_skb: dev=ens5 skbaddr=00000000396063ad len=52
          <idle>-0       [000] ..s1. 35522.455066: netif_receive_skb: dev=ens5 skbaddr=00000000d38978cf len=52

関数グラフ

指定した関数の子関数をヒストグラム形式で表示できます。

> echo do_nanosleep > set_graph_function
> echo function_graph > current_tracer
> sleep 1
> head -n 20 trace
# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |
 0)               |  do_nanosleep() {
 0)               |    hrtimer_start_range_ns() {
 0)   0.461 us    |      _raw_spin_lock_irqsave();
 0)   0.284 us    |      ktime_get();
 0)               |      get_nohz_timer_target() {
 0)   0.192 us    |        idle_cpu();
 0)   0.486 us    |      }
 0)   0.424 us    |      enqueue_hrtimer();
 0)   0.199 us    |      _raw_spin_unlock_irqrestore();
 0)   3.172 us    |    }
 0)               |    schedule() {
 0)   0.164 us    |      rcu_note_context_switch();
 0)               |      raw_spin_rq_lock_nested() {
 0)   0.141 us    |        _raw_spin_lock();
 0)   0.408 us    |      }
 0)               |      update_rq_clock() {
> echo nop > current_tracer
> echo > set_graph_function

trace-cmd

ftrace のフロントエンドコマンド。 上述のようにファイルに色々書き込んだりせず、コマンドラインで簡単に ftrace が使えます。

関数プロファイラ

> trace-cmd record -p function -l vfs* sleep 10
  plugin 'function'
CPU0 data recorded at offset=0x22e000
    800 bytes in size (8192 uncompressed)
CPU1 data recorded at offset=0x22f000
    3028 bytes in size (28672 uncompressed)
> trace-cmd report --profile
cpus=2

task: systemd-oomd-733
  Event: func: vfs_getattr_nosec() (168)
  Event: func: vfs_open() (144)
  Event: func: vfs_fstat() (168)
  Event: func: vfs_read() (296)

task: zsh-43491
  Event: func: vfs_write() (1)

task: nvim-43630
  Event: func: vfs_getattr_nosec() (25)
  Event: func: vfs_statx() (25)
  Event: func: vfs_open() (5)
  Event: func: vfs_fstat() (5)
  Event: func: vfs_statx_path.part.0() (20)

関数トレーシング

> trace-cmd record -p function -l vfs* sleep 10
  plugin 'function'
CPU0 data recorded at offset=0x22e000
    2279 bytes in size (24576 uncompressed)
CPU1 data recorded at offset=0x22f000
    1078 bytes in size (8192 uncompressed)
> trace-cmd report
cpus=2
           sleep-44363 [001] ..... 92547.229353: function:             vfs_open
           sleep-44363 [001] ..... 92547.230695: function:             vfs_open
           sleep-44363 [001] ..... 92547.231241: function:             vfs_open
           sleep-44363 [001] ..... 92547.231245: function:             vfs_fstat
           sleep-44363 [001] ..... 92547.231245: function:                vfs_getattr_nosec

関数グラフ

> trace-cmd record -p function_graph --max-graph-depth=3 -g vfs_read ls
  plugin 'function_graph'
backup_dotfiles  trace-cmd  trace.dat.cpu0  trace.log
dotfiles         trace.dat  trace.dat.cpu1
CPU0 data recorded at offset=0x22e000
    606 bytes in size (4096 uncompressed)
CPU1 data recorded at offset=0x22f000
    844 bytes in size (4096 uncompressed)
> trace-cmd report | cut -c 66-

        1.464 us   |  mutex_unlock(); (ret=0xffff98109de23100)
                   |  vfs_read() {
                   |    rw_verify_area() {
        0.474 us   |      security_file_permission(); (ret=0x0)
        0.954 us   |    } (ret=0x0)
                   |    btrfs_file_read_iter() {
        1.180 us   |      filemap_read(); (ret=0x340)
        1.540 us   |    } (ret=0x340)
        0.144 us   |    __fsnotify_parent(); (ret=0x0)
        4.208 us   |  } (ret=0x340)
                   |  vfs_read() {
                   |    rw_verify_area() {
        0.331 us   |      security_file_permission(); (ret=0x0)
        0.706 us   |    } (ret=0x0)
                   |    btrfs_file_read_iter() {
        1.219 us   |      filemap_read(); (ret=0x340)
        1.496 us   |    } (ret=0x340)
        0.214 us   |    __fsnotify_parent(); (ret=0x0)
        3.210 us   |  } (ret=0x340)

他にも trace-cmd ではクライアント・サーバー方式でイベントをトレースできるらしい