詳解 システム・パフォーマンス - 第14章：Ftrace

Ftrace とは

Linux カーネルの公式内蔵トレーサー（Steven Rostedt 作）。
カーネルコードに変更なしで、カーネル内部の動作を追跡できる。

• ディレクトリ /sys/kernel/debug/tracing/ でファイル経由で操作
• perf ftrace コマンドが使いやすいラッパーとして提供
• BPF/eBPF より低レベルで、カーネルの内部構造を直接追える

---

Ftrace の機能

機能	説明
Function Tracer	カーネル関数の呼び出しをすべて記録
Function Graph Tracer	関数の入口・出口を記録（コールツリー表示）
Latency Tracers	スケジューリングレイテンシ・IRQ レイテンシを計測
Event Tracing	tracepoint イベント（block, sched, net 等）を記録
Stack Tracer	カーネルスタックのサンプリング

---

perf ftrace ラッパー（推奨）

直接ファイル操作より perf ftrace が使いやすい。

# 特定プロセスの関数呼び出しをトレース
sudo perf ftrace -p <PID>

# カーネル関数のレイテンシ（ヒストグラム）
sudo perf ftrace latency -T do_sys_open
# 出力：
#  do_sys_open() latency histogram (us):
#    usecs    : count     distribution
#      0 - 1  :    100   |**********|
#      2 - 3  :     50   |*****     |
#      4 - 7  :     10   |*         |
#     32 - 63 :      2   |          | ← 遅いケース

# 関数プロファイル（合計時間・呼び出し回数）
sudo perf ftrace profile -p <PID>
# Function Name       Calls  Time Total   Time Avg   Time Max
# vfs_read             1000     50.0ms      50us     100us
# ext4_file_read_iter   900     45.0ms      50us     100us

# BPF バックエンドで高精度計測
sudo perf ftrace latency -T vfs_read --use-bpf

---

tracefs の直接操作

/sys/kernel/debug/tracing/ を直接操作する方法。
より細かい制御が可能だが、手順が煩雑。

# tracefs のマウント確認
mount | grep tracefs
# または
ls /sys/kernel/debug/tracing/

# 利用可能なトレーサー一覧
cat /sys/kernel/debug/tracing/available_tracers
# blk function function_graph hwlat irqsoff mmiotrace nop preemptirqsoff preemptoff wakeup wakeup_dl wakeup_rt

# 利用可能なカーネル関数一覧
cat /sys/kernel/debug/tracing/available_filter_functions | grep "tcp"

Function Tracer の使い方

# 1. トレーサーを設定
echo function > /sys/kernel/debug/tracing/current_tracer

# 2. フィルター（特定関数のみ）
echo 'do_sys_open' > /sys/kernel/debug/tracing/set_ftrace_filter
# または特定プロセスのみ
echo <PID> > /sys/kernel/debug/tracing/set_ftrace_pid

# 3. トレース開始
echo 1 > /sys/kernel/debug/tracing/tracing_on

# 4. しばらく待つ
sleep 5

# 5. トレース停止
echo 0 > /sys/kernel/debug/tracing/tracing_on

# 6. 結果を確認
cat /sys/kernel/debug/tracing/trace | head -30
# <idle>-0     [000] d..3 12345.678901: do_sys_open <-ksys_open

# 7. クリーンアップ
echo nop > /sys/kernel/debug/tracing/current_tracer
echo > /sys/kernel/debug/tracing/set_ftrace_filter
echo > /sys/kernel/debug/tracing/set_ftrace_pid

Function Graph Tracer（コールツリー表示）

# コールツリーを視覚的に表示
echo function_graph > /sys/kernel/debug/tracing/current_tracer
echo <PID> > /sys/kernel/debug/tracing/set_ftrace_pid
echo 1 > /sys/kernel/debug/tracing/tracing_on
sleep 3
echo 0 > /sys/kernel/debug/tracing/tracing_on
cat /sys/kernel/debug/tracing/trace | head -50

# 出力例：
# | do_sys_open() {
# |   getname() {
# |     kmem_cache_alloc() { /* 2.500 us */ }
# |   } /* 10.000 us */
# |   vfs_open() {
# |     ext4_file_open() { /* 50.000 us */ }
# |   } /* 60.000 us */
# | } /* 80.000 us */

---

Event Tracing（tracepoint）

カーネル内の特定イベントを記録する。

# 利用可能なイベント一覧
perf list tracepoint 2>/dev/null | head -30
ls /sys/kernel/debug/tracing/events/

# 主要なイベントカテゴリ：
# block: ディスクI/O (block_rq_issue, block_rq_complete)
# sched: スケジューラ (sched_switch, sched_wakeup)
# net: ネットワーク (net_dev_queue, net_dev_xmit)
# syscalls: システムコール
# ext4, xfs: ファイルシステム操作

# ブロックI/Oのイベントを記録
echo 1 > /sys/kernel/debug/tracing/events/block/block_rq_issue/enable
echo 1 > /sys/kernel/debug/tracing/events/block/block_rq_complete/enable
echo 1 > /sys/kernel/debug/tracing/tracing_on
sleep 5
echo 0 > /sys/kernel/debug/tracing/tracing_on
cat /sys/kernel/debug/tracing/trace | grep -E "block_rq" | head -20

# perf でイベント記録（推奨）
sudo perf record -e block:block_rq_issue,block:block_rq_complete -a -g sleep 10
perf script | head -30

---

Latency Tracers

スケジューリングレイテンシ（プロセスが実行待ちになる時間）を計測する。

# wakeup tracer: タスクが起床してから実際に CPU を得るまでの時間
echo wakeup > /sys/kernel/debug/tracing/current_tracer
echo 1 > /sys/kernel/debug/tracing/tracing_on
sleep 3
echo 0 > /sys/kernel/debug/tracing/tracing_on
cat /sys/kernel/debug/tracing/trace

# irqsoff tracer: 割り込み禁止中の最大時間を記録（カーネルレイテンシ調査）
echo irqsoff > /sys/kernel/debug/tracing/current_tracer
echo 1 > /sys/kernel/debug/tracing/tracing_on
sleep 3
echo 0 > /sys/kernel/debug/tracing/tracing_on
cat /sys/kernel/debug/tracing/trace

# 最大レイテンシ値を確認
cat /sys/kernel/debug/tracing/tracing_max_latency

---

Ftrace vs BPF/perf の使い分け

ツール	向いている用途
Ftrace	カーネル内部の詳細な関数トレース・コールツリー表示
perf	CPU プロファイリング・フレームグラフ・ハードウェアカウンタ
BPF/bpftrace	カスタムな集計・ヒストグラム・複数イベントの組み合わせ

---

よくある使用シナリオ

スケジューリングレイテンシが疑われる

# タスクが起床してから CPU を得るまでの最大時間
sudo perf ftrace latency -T __schedule --use-bpf

# または wakeup tracer
echo wakeup > /sys/kernel/debug/tracing/current_tracer

カーネル関数の実行時間を知りたい

# ext4 の読み込み操作レイテンシ
sudo perf ftrace latency -T ext4_file_read_iter

# VFS 読み込みレイテンシ
sudo perf ftrace latency -T vfs_read

ディスクI/Oのカーネル内経路を追いたい

# ブロックI/Oのコールツリーを表示
echo function_graph > /sys/kernel/debug/tracing/current_tracer
echo 'blk*,bio*,submit_bio*' > /sys/kernel/debug/tracing/set_ftrace_filter
echo 1 > /sys/kernel/debug/tracing/tracing_on
# I/Oが発生するコマンドを実行
dd if=/dev/zero of=/tmp/test bs=4k count=1000
echo 0 > /sys/kernel/debug/tracing/tracing_on
cat /sys/kernel/debug/tracing/trace | head -50