ftraceのfunctionトレーサやfunction graphトレーサを使うと、カーネルの関数呼び出し処理を追いかけることができます。
ftraceの諸機能をカーネルで有効にする方法については前回の投稿を参照してください。ただし今回書いている内容は、恐らくFedoraやUbuntuのカーネルではデフォルトで有効になっています。
関数コールトレーサ
ftraceにはLinuxカーネル内の関数呼び出しをトレースする関数コールトレーサ・関数コールグラフトレーサをサポートしています。
関数コールトレーサはfunctionを、関数コールグラフトレーサは function_graph を、/sys/kerne/debug/tracing/current_tracerに書き込むだけで利用できます。
# echo function > /sys/kernel/debug/tracing/current_tracer
これらの関数コール（グラフ）トレーサは、インライン展開されていないすべての関数呼び出しをトレースし、可視化することができますが、当然のことにカーネルの処理が非常に重くなり、また出てくるデータの量も膨大になります。
関数コールトレーサのフィルタ
これらの関数コールトレーサには、複数の方法でフィルタをかけることができます。
- 関数名ベースのフィルタ
- PIDベースのフィルタ
関数名ベースのフィルタ
関数名ベースのフィルタには、「指定した関数だけトレースするフィルタ(set_ftrace_filter)」と、「指定した関数をトレースしないフィルタ(set_ftrace_notrace)」があります。関数名には限定的ですがワイルドカード(*)も使うことができます。例えばvfsを関数名に含む関数だけをトレースする場合は、次のようにします
# echo '*vfs*' > /sys/kernel/debug/tracing/set_ftrace_filter
ここで/sys/kernel/debug/tracing/traceファイルを読むと、以下のようにvfs関係の関数だけがトレースされていることがわかります。
# tracer: function
#
# entries-in-buffer/entries-written: 190/190 #P:8
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
gdbus-8688 [003] .... 105981.564554: vfs_read <-SyS_read
bamfdaemon-8170 [002] .... 105981.564584: vfs_writev <-do_writev
gdbus-8688 [003] .... 105981.564590: vfs_read <-SyS_read
gdbus-8688 [003] .... 105981.564590: __vfs_read <-vfs_read
compiz-8331 [007] .... 105981.564706: vfs_writev <-do_writev
gdbus-8688 [003] .... 105981.564822: vfs_write <-SyS_write
gdbus-8688 [003] .... 105981.564823: __vfs_write <-vfs_write
gdbus-8688 [003] .... 105981.983184: vfs_read <-SyS_read
gdbus-8688 [003] .... 105981.983187: __vfs_read <-vfs_read
記録されている関数の読み方ですが、
A <- B
となっているのは、関数Bから関数Aが呼び出された、ということを示しています。
一方、spinlock関係の関数だけをトレースから外すには次のようにします。
# echo '*_spin_*' > /sys/kernel/debug/tracing/set_ftrace_notrace
ちなみに、このようにしてワイルドカードで指定したフィルタは、それぞれのファイルを読みだせば、どのように解釈されたかが示されます。
# cat /sys/kernel/debug/tracing/set_ftrace_notrace
queued_spin_unlock_wait
native_queued_spin_lock_slowpath
__pv_queued_spin_lock_slowpath
__pv_queued_spin_unlock_slowpath
__raw_spin_lock_init
do_raw_spin_lock
do_raw_spin_trylock
do_raw_spin_unlock
rwsem_spin_on_owner
_raw_spin_lock
_raw_spin_lock_bh
_raw_spin_lock_irq
_raw_spin_trylock
_raw_spin_trylock_bh
_raw_spin_unlock
_raw_spin_unlock_bh
_raw_spin_unlock_irq
_raw_spin_unlock_irqrestore
_raw_spin_lock_irqsave
__i915_spin_request [i915]
モジュール名ベースのフィルタ
また、どちらも特定のカーネルモジュール（ドライバ）に含まれる関数だけ指定する方法(:mod:)もあります。例えば、btrfsモジュールに含まれる関数だけをトレースしたい場合は以下のようにします。
# echo ':mod:btrfs' > /sys/kernel/debug/tracing/set_ftrace_filter
カーネルのデバッグをしている場合、モジュールをデバッグする場合はともかく、通常は実行パスがわからないので、ほぼすべての関数をトレースすることになりますが、これらの大雑把な方法では、ターゲットとなる処理を絞り込むのは面倒です。多分cscopeやctagsと連携すると幸せになれるのですが・・・。
PIDベースのフィルタ
そこでPIDフィルタの出番です。ターゲットとなる処理を行うプログラムがわかっている場合、そのプログラムのPIDを与えることで、そのプロセスの実行した関数呼び出しだけをトレースすることができます（実際にはすべての関数をトレースしつつ、条件に合う場合だけバッファに書いています。）
例えばPID=1000のプロセスだけをトレースしたい場合は以下のようにします。
# echo 1000 > set_ftrace_pid
PID（や関数名）フィルタは追記することができます。
# echo 1001 >> set_ftrace_pid
そのまま書き込んでしまうと、ファイルのように上書きされるので注意が必要です。
一方、対象となるテストプログラムはわかっているものの、常時動作しているプログラムではなく、一瞬で実行して終わってしまうようなプログラムの場合、次のようなコマンド実行の仕方をするとpidを設定できます。(ここではテストプログラムをTEST_CMDとします）
# (cut -f4 -d" " /proc/self/stat > set_ftrace_pid; exec TEST_CMD)
一応説明すると、（）でサブシェルを起動し、サブシェルから起動したcutプログラムの親PID（つまりサブシェルのPID）を/proc/self/statから取得し、ftraceのPIDフィルタに設定した後、対象のプログラムをexecで起動することで、同じPIDを継続して使うようにしています。サブシェルを使うのは、execを使うと現在のシェルを終了してしまうためです。
フィルタのクリア
一度設定したフィルタをクリアするには、空文字("")を上書きモードで書き込みます。
# echo > set_ftrace_pid
イベントトレース（トリガ）と関数コールトレーサのコラボ
さて、もし更にトレースする範囲を絞り込みたい場合、例えば特定の関数の内部の処理だけをトレースしたい場合、2つの方法があります。
一つはソースコードの静的解析から、呼び出している関数を列挙し、set_ftrace_filterとset_ftrace_notraceを適切に設定する方法です。この方法は静的解析をするうちにコードの内容に慣れることができるので、お勧めではありますが、時間がかかります。またカーネル内でよく使われるcallbackパターンなどがあると、探索範囲が増えるので面倒です。（大抵の場合、そのあたりはトレースしなくても良いんですが）
トレース期間の限定
もうひとつの方法は、特定の関数内やイベントに囲まれた範囲のみをトレースする方法です。この方法はトレースを開始したい場所と終了したい場所を指定するだけなので、大規模な静的解析をする前に、手軽に試せるという利点があります。（ただし、いくつかの注意点もあります）
例えばdo_readv_writevを例にした場合、この関数内部の呼び出しをトレースする方法は以下のようになります。
1.まずトレースを開始する場所と終了したい場所にkprobeのイベントを埋め込みます。
# echo p:probe/start_trace do_readv_writev > /sys/kernel/debug/tracing/kprobe_events
# echo r:probe/end_trace do_readv_writev >> /sys/kernel/debug/tracing/kprobe_events
2.これらのイベントにtraceonとtraceoffのトリガーを仕込みます
# echo traceon > /sys/kernel/debug/tracing/events/probe/start_trace/trigger
# echo traceoff > /sys/kernel/debug/tracing/events/probe/end_trace/trigger
3.また、これは必須ではないですが、トレースの目安にするために新たに追加したイベントを有効にしておきます。
（トリガー自体はイベントがenabledでなくても動作します）
# echo 1 > /sys/kernel/debug/tracing/events/probe/start_trace/enable
# echo 1 > /sys/kernel/debug/tracing/events/probe/end_trace/enable
4.後は関数コールグラフトレーサなどを有効にして、traceファイルを読みだせば、do_readv_writev（）内部の
関数呼び出しグラフが作れます。
# echo function_graph > /sys/kernel/debug/tracing/current_tracer
ftraceの仕組みでは、関数の呼び出しを捉えたり、トレースイベントを捉える仕組みと、そこから得た情報を書き込む仕組みが分かれています（前者はperfなどからも使われる）。traceon/offはこの内後者だけを無効化するフラグを制御します。
per-cpuトレースデータ
しかし、この制御フラグはグローバルなフラグであるため、SMP環境では他のCPUのトレースも有効になり、出力がマージされていて見えにくい場合があります。
この場合、以下のようにper_cpu/cpuX/traceファイルを使って各CPUごとに意味のある結果を参照しましょう。うまく探すと、以下のような綺麗なグラフを可視化できます。
# less /sys/kernel/debug/tracing/per_cpu/cpu3/trace
...
3) | /* start_trace: (do_readv_writev+0x0/0x210) */
3) | do_readv_writev() {
3) | rw_copy_check_uvector() {
3) | __might_fault() {
3) | __might_sleep() {
3) 0.057 us | ___might_sleep();
3) 0.388 us | }
3) 0.680 us | }
3) 1.003 us | }
3) | rw_verify_area() {
3) | security_file_permission() {
3) | apparmor_file_permission() {
3) 0.041 us | common_file_perm();
3) 0.333 us | }
3) 0.652 us | }
3) 0.959 us | }
3) | do_iter_readv_writev() {
3) | sock_write_iter() {
3) | sock_sendmsg() {
3) 0.038 us | security_socket_sendmsg();
3) | unix_stream_sendmsg() {
3) | wait_for_unix_gc() {
3) | __might_sleep() {
3) 0.040 us | ___might_sleep();
3) 0.345 us | }
3) 0.040 us | _cond_resched();
3) 0.985 us | }
3) 0.041 us | security_socket_getpeersec_dgram();
3) | sock_alloc_send_pskb() {
3) | alloc_skb_with_frags() {
3) | __alloc_skb() {
3) | kmem_cache_alloc_node() {
3) | __might_sleep() {
3) 0.040 us | ___might_sleep();
3) 0.332 us | }
3) 0.037 us | _cond_resched();
3) | memcg_kmem_get_cache() {
3) 0.071 us | get_mem_cgroup_from_mm();
3) + 40.154 us | }
3) | trampoline_handler() {
3) | kretprobe_hash_lock() {
3) | _raw_spin_lock_irqsave() {
3) 0.045 us | do_raw_spin_lock();
3) 0.328 us | }
3) 0.617 us | }
3) | /* end_trace: (vfs_writev+0x3c/0x50 <- do_readv_writev) */
また、この手法は他にも以下のような問題があります。
- 単なるフラグであるため、並行して複数のスレッドが同じ関数呼び出しを行うと、思わぬところで記録が中断される可能性がある。
- 内部でsleepする関数だと、sleepしている間他のスレッドが処理している関数呼び出しも記録される。
イベントに対するPIDフィルタ
上記問題の対策としては、PIDフィルタを組み合わせる、対象となるプログラムをCPU affinityなどで特定のCPUに限定するなどの方法があります。
ちなみに、イベントトレース用のPIDフィルタと関数呼び出しトレース用のPIDフィルタは設定が違っているので注意が必要です。イベント用にはset_event_pidファイルを使いますが、上記のトリガーもこの設定でしか発火しません。例えば対象のプログラムが決まっている場合、以下のようにset_ftrace_pidではなくset_event_pidを設定します。
# echo 1000 > set_event_pid
このようにして、単体ではデータ量が膨大になりがちな関数コールトレーサを、対象や範囲・期間を限定することで使いやすくするという話でした。