ftraceの使い方 - へにゃぺんて＠日々勉強のまとめ

ftraceの使い方については、以下の記事でも紹介しましたが、

ftraceを試してみました - へにゃぺんて＠日々勉強のまとめ

過去には紹介しなかった使い方も分かったので、あらためてまとめます。

過去に紹介したときは、
「関数単位でカーネルの実行状況のトレースログを出してくれる機能」
という紹介でしたが、実は他にも機能があります。

なお以降の説明は、Linux 3.14.51で確認したものです。
また、debugfsのマウントポイントをで略記しています。

参考: debugfsのマウント方法
(マウントポイント /sys/kernel/debug の場合)

sudo mount -t debugfs none /sys/kernel/debug

カーネル コンフィギュレーションの変更

ftraceを使用する際もカーネルコンフィギュレーションの変更が必要です。

Kernel hacking
- [*] Tracers <- 有効化
  - [*] Kernel Function Tracer <- 有効化
    - [*] Kernel Function Graph Tracer <- 有効化

上記の通り、有効化してカーネルをビルドしてください。

ftraceの有効化

カーネルコンフィギュレーションを変更して作成したカーネルでブートしたあと、
まずは、ftraceが有効になっているかを以下のように確認します。

$ sudo cat /proc/sys/kernel/ftrace_enabled
1

ftrace_enabledから1が読み出せる場合は有効になっています。

有効になっていない場合は、ftrace_enabledに1を書いて有効化してください。

# echo 1 > /proc/sys/kernel/ftrace_enabled
あるいは、
$ echo 1 | sudo tee /proc/sys/kernel/ftrace_enabled

※ ftrace_enabledは所有者(root)にしか書き込み権限が無いので、sudo＋リダイレクトでは書き込めません

なお、sysctlコマンドを使用して、以下のように設定することもできます。

$ sudo sysctl kernel.ftrace_enabled=1

trace-cmdを使用した関数単位トレース

ここではまず、trace-cmdコマンドを使用した関数単位でのトレース方法を紹介します。

trace-cmdのソースコードをダウンロード(Gitリポジトリのclone)し、

$ git clone git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/trace-cmd.git

ビルド・インストールします。

$ cd trace-cmd/
$ make
$ sudo make install

なお、sudo make install完了後、

Note: to install the gui, type "make install_gui"
to install man pages, type "make install_doc"

「GUIが必要なら、"make install_gui"
man pageが必要なら"make install_doc"」
と表示が出ます。必要に応じてインストールしてください。

make install_guiは試していませんが、
make install_docには、"asciidoc"パッケージが必要です。

$ sudo apt-get install asciidoc

でインストールしておいてください。

trace-cmdコマンドを使用方法について、
例えばlsコマンド実行時のカーネルの動きをトレースしたい場合は、
以下のコマンドを実行します。

sudo trace-cmd record -p function ls

トレース結果は"trace.dat"というファイルに保存されます。
(なお、保存先は-oオプションで指定できます。)

そして、保存したログを閲覧するには以下のコマンドを実行します。

$ trace-cmd report | lv

ただし、↑のコマンドは、トレース結果がカレントディレクトリに"trace.dat"という名前で
保存されていることが条件です。
別名で保存している場合は、-iオプションで入力ファイルを指定できます。

trace-cmd reportでは、以下のような結果が得られます。(先頭部分のみ抜粋)

cpus=4
              ls-13012 [003]  9874.688303: function:             mutex_unlock
              ls-13012 [003]  9874.688304: function:             __mutex_unlock_slowpath
              ls-13012 [003]  9874.688304: function:                _raw_spin_lock
              ls-13012 [003]  9874.688304: function:                wake_up_process
              ls-13012 [003]  9874.688304: function:                try_to_wake_up
              ls-13012 [003]  9874.688304: function:                   _raw_spin_lock_irqsave
              ls-13012 [003]  9874.688304: function:                   task_waking_fair
              ls-13012 [003]  9874.688304: function:                   select_task_rq_fair
              ls-13012 [003]  9874.688305: function:                      source_load
              ls-13012 [003]  9874.688305: function:                      target_load
              ls-13012 [003]  9874.688305: function:                      effective_load.isra.50
              ls-13012 [003]  9874.688305: function:                      effective_load.isra.50
              ls-13012 [003]  9874.688305: function:                      select_idle_sibling
              ls-13012 [003]  9874.688305: function:                         idle_cpu
              ls-13012 [003]  9874.688305: function:                   _raw_spin_lock
              ls-13012 [003]  9874.688306: function:                   ttwu_do_activate.constprop.93
              ls-13012 [003]  9874.688306: function:                      activate_task
              ls-13012 [003]  9874.688306: function:                      enqueue_task
              ls-13012 [003]  9874.688306: function:                         update_rq_clock.part.83
              ls-13012 [003]  9874.688306: function:                      enqueue_task_fair
              ls-13012 [003]  9874.688306: function:                         update_curr

"ls"コマンドを実行中のカーネルの動きを関数単位でトレースしていることがわかります。

trace-cmdには他にも機能があります。
詳しくは、man trace-cmdを参照してください。

debugfsを使用した方法

debugfsからftraceの機能を利用できます。

/tracing/
にftraceの機能を利用するためのファイルが配置されています。

debugfs経由でのftraceでは、単なる関数単位のトレースではなく、
「スケジューラ」・「システムコール」・「割り込み」などのイベントをトレースできます。

使用中のカーネルで利用可能なトレースイベントは、
/tracing/events/
の中を除くと確認できます。

$ sudo ls <debugfs>/tracing/events/
block         hda           kmem          nmi           sched         udp
cfg80211      hda_intel     mac80211      oom           scsi          vmscan
compaction    header_event  mce           pagemap       signal        vsyscall
drm           header_page   migrate       power         skb           workqueue
enable        i915          module        printk        sock          writeback
exceptions    iommu         napi          random        sunrpc
ext4          irq           net           ras           swiotlb
filemap       irq_vectors   nfs           raw_syscalls  task
ftrace        jbd2          nfs4          rcu           timer

ここでは、試しに、スケジューラのイベントをトレースしてみます。
そのためには、/tracing/events/sched/ ディレクトリの中にある
"enable"ファイルに"1"を書き込みます。

$ echo 1 | sudo tee <debugfs>/tracing/events/sched/enable

そして、/tracing/trace をcatなどで読みだすと、
以下のようにスケジューラのイベントのトレース結果を確認できます。

# tracer: nop
#
# entries-in-buffer/entries-written: 6663/6663   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
             tee-13632 [003] d... 12936.308699: sched_wakeup: comm=kworker/3:1 pid=13299 prio=120 success=1 target_cpu=003
             tee-13632 [003] .... 12936.308767: sched_process_exit: comm=tee pid=13632 prio=120
             tee-13632 [003] d... 12936.308772: sched_stat_runtime: comm=tee pid=13632 runtime=105223 [ns] vruntime=261513731595 [ns]
             tee-13632 [003] d... 12936.308773: sched_stat_runtime: comm=tee pid=13632 runtime=1259 [ns] vruntime=1394219007352 [ns]
             tee-13632 [003] d... 12936.308778: sched_wake_idle_without_ipi: cpu=0
             tee-13632 [003] d... 12936.308779: sched_wakeup: comm=sudo pid=13631 prio=120 success=1 target_cpu=000
             tee-13632 [003] d... 12936.308779: sched_stat_runtime: comm=tee pid=13632 runtime=6344 [ns] vruntime=1394219013696 [ns]
             tee-13632 [003] d... 12936.308780: sched_switch: prev_comm=tee prev_pid=13632 prev_prio=120 prev_state=x ==> next_comm=kworker/3:1 next_pid=13299 next_prio=120
     kworker/3:1-13299 [003] d... 12936.308784: sched_wake_idle_without_ipi: cpu=2
     kworker/3:1-13299 [003] d... 12936.308784: sched_wakeup: comm=screen pid=1076 prio=120 success=1 target_cpu=002
     kworker/3:1-13299 [003] d... 12936.308785: sched_stat_runtime: comm=kworker/3:1 pid=13299 runtime=5466 [ns] vruntime=1394210026004 [ns]
          <idle>-0     [002] d... 12936.308786: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=screen next_pid=1076 next_prio=120
     kworker/3:1-13299 [003] d... 12936.308789: sched_switch: prev_comm=kworker/3:1 prev_pid=13299 prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120
          <idle>-0     [000] d... 12936.308797: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=sudo next_pid=13631 next_prio=120
          screen-1076  [002] dN.. 12936.308811: sched_wakeup: comm=kworker/2:0 pid=17397 prio=120 success=1 target_cpu=002
          screen-1076  [002] dN.. 12936.308812: sched_stat_runtime: comm=screen pid=1076 runtime=26836 [ns] vruntime=3991760921 [ns]
          screen-1076  [002] d... 12936.308812: sched_switch: prev_comm=screen prev_pid=1076 prev_prio=120 prev_state=R ==> next_comm=kworker/2:0 next_pid=17397 next_prio=120
     kworker/2:0-17397 [002] d... 12936.308815: sched_migrate_task: comm=xterm pid=1044 prio=120 orig_cpu=0 dest_cpu=3
            sudo-13631 [000] .... 12936.308815: sched_process_wait: comm=sudo pid=13632 prio=120
     kworker/2:0-17397 [002] d... 12936.308816: sched_wake_idle_without_ipi: cpu=3

ただし、この結果だとスケジューラに関していろいろなイベントが起きている様子はわかりますが、
情報が多すぎます。

実は、スケジューラのイベントの中で特定のイベントのみトレースを有効化することができます。
/tracing/events/sched/ には、"enable"ファイル以外にも、以下のディレクトリがあります。

# ls <debugfs>/tracing/events/sched/
enable                  sched_process_exit      sched_stat_wait
filter                  sched_process_fork      sched_stick_numa
sched_kthread_stop      sched_process_free      sched_swap_numa
sched_kthread_stop_ret  sched_process_wait      sched_switch
sched_migrate_task      sched_stat_blocked      sched_wait_task
sched_move_numa         sched_stat_iowait       sched_wakeup
sched_pi_setprio        sched_stat_runtime      sched_wakeup_new
sched_process_exec      sched_stat_slee

"enable"、"filter"はファイルで、その他はディレクトリです。
ここに並ぶディレクトリは、スケジューラに関してトレースできるイベントで、
先ほど、schedディレクトリ直下のenableに1を書くことで、すべて有効化していました。

今度は、Forkイベントのみトレースしてみます。

まずは、先ほどの有効化を元に戻します(無効化)。

$ echo 0 | sudo tee <debugfs>/tracing/events/sched/enable

そして、sched/sched_process_forkディレクトリのenableに1を書き、Forkイベントのみトレースを有効化します。

$ echo 1 | sudo tee <debugfs>/tracing/events/sched/sched_process_fork/enable

このまま再度traceファイルを読みだすと、スケジューラのイベントすべて有効だった時の結果が残っているので、
一旦クリアします。(空文字を書き込みます。)

$ echo | sudo tee /debug/tracing/trace

再度、/tracing/traceを読みだすと、今度はForkイベントのみトレース結果に現れていることがわかります。

# tracer: nop
#
# entries-in-buffer/entries-written: 5/5   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
           emacs-1100  [002] .... 13732.423490: sched_process_fork: comm=emacs pid=1100 child_comm=emacs child_pid=13799
 x-window-manage-855   [002] .... 13733.807122: sched_process_fork: comm=x-window-manage pid=855 child_comm=x-window-manage child_pid=13800
              sh-13800 [002] .... 13733.808288: sched_process_fork: comm=sh pid=13800 child_comm=sh child_pid=13801
             zsh-22818 [003] .... 13739.756022: sched_process_fork: comm=zsh pid=22818 child_comm=zsh child_pid=13802
            sudo-13802 [002] .... 13739.763045: sched_process_fork: comm=sudo pid=13802 child_comm=sudo child_pid=13803

なお、トレース結果を確認するファイルとして、traceの他に、trace_pipeがあります。
両者の違いは以下のとおりです。

trace
- 読みだすと、トレースログの先頭から末尾まで吐き出し、EOFを返す
- 再度読みだすと、また先頭から吐き出す
trace_pipe
- 読み出すと、前回最後に吐き出した次の行から末尾まで吐き出し、EOFは返さずに新たに得られた結果を随時吐き出す

その他、詳しくは以下のドキュメントを参照してください。

Linux カーネルソースディレクトリ/Documentation/trace/ftrace.txt
Linux カーネルソースディレクトリ/Documentation/trace/events.txt