eBPF可観測性の実践 — bpftraceでシステムのブラックボックスを開く

               観測対象レイヤとeBPFフック
+------------------------------------------------------------+
| アプリケーション   <── uprobe / USDT (関数遅延、GCイベント)  |
+------------------------------------------------------------+
| ライブラリ(libc)   <── uprobe (malloc, pthreadなど)         |
+------------------------------------------------------------+
| システムコール境界 <── tracepoint syscalls:* (open, read...)|
+------------------------------------------------------------+
| カーネルサブシステム                                         |
|   VFS/ファイルシステム <── kprobe/kfunc (vfs_readなど)       |
|   ブロック層       <── tracepoint block:* (IO遅延)          |
|   ネットワークスタック <── kprobe tcp_* / tracepoint sock:* |
|   スケジューラ     <── tracepoint sched:* (ランキュー待ち)   |
+------------------------------------------------------------+
| ハードウェアイベント <── perf_event (CPUサイクル、キャッシュミス) |
+------------------------------------------------------------+

probe /filter/ { action }

probe  : どこにアタッチするか (tracepoint, kprobe, uprobe, profile...)
filter : どのイベントだけを見るか (pid == 1234 など、省略可)
action : 何をするか (出力、マップへ集計)

sudo bpftrace -e 'tracepoint:syscalls:sys_enter_openat
  { printf("%-16s %s\n", comm, str(args->filename)); }'

sudo bpftrace -e 'tracepoint:syscalls:sys_enter_execve
  { printf("%-16s -> %s\n", comm, str(args->filename)); }'

sudo bpftrace -e 'tracepoint:raw_syscalls:sys_enter
  { @[comm] = count(); }'

sudo bpftrace -e '
tracepoint:syscalls:sys_enter_read { @start[tid] = nsecs; }
tracepoint:syscalls:sys_exit_read /@start[tid]/
  { @usecs = hist((nsecs - @start[tid]) / 1000); delete(@start[tid]); }'

sudo bpftrace -e 'kprobe:tcp_connect
  { printf("%-16s pid=%d\n", comm, pid); }'

sudo bpftrace -e 'tracepoint:block:block_rq_issue
  { @bytes = hist(args->bytes); }'

sudo bpftrace -e 'tracepoint:block:block_rq_issue
  { @[comm] = sum(args->bytes); }'

sudo bpftrace -e 'profile:hz:99 { @[kstack] = count(); }'

sudo bpftrace -e 'software:page-faults:1 { @[comm] = count(); }'

sudo bpftrace -e 'tracepoint:syscalls:sys_enter_kill
  { printf("%s (pid %d) -> pid %d, sig %d\n",
           comm, pid, args->pid, args->sig); }'

sudo bpftrace -l 'tracepoint:syscalls:*' | head -20
sudo bpftrace -lv 'tracepoint:syscalls:sys_enter_openat'   # 引数構造を確認

# 10msより遅いext4操作のみ出力
sudo ext4slower-bpfcc 10

# 1秒間隔でブロックIO遅延ヒストグラムを出力
sudo biolatency-bpfcc -m 1

# コンテナ込みの全TCPセッション寿命を観察
sudo tcplife-bpfcc

sudo execsnoop-bpfcc      # 想定外のプロセス急増の有無 (cron、ヘルスチェックなど)
sudo runqlat-bpfcc 5 1    # CPU競合: ランキュー待ち分布
sudo biolatency-bpfcc 5 1 # ディスク: IO遅延分布
sudo tcpretrans-bpfcc     # ネットワーク: 再送発生の有無
sudo syscount-bpfcc -L -d 5  # シスコール遅延トップ

usecs               : count     distribution
   128 -> 255       : 1402     |**************************              |
   256 -> 511       : 2012     |****************************************|
   512 -> 1023      : 803      |***************                         |
  1024 -> 2047      : 95       |*                                       |
  ...
 65536 -> 131071    : 41       |                                        |
131072 -> 262143    : 17       |                                        |

# 経路A: perfベース
sudo perf record -F 99 -a -g -- sleep 30
sudo perf script | stackcollapse-perf.pl | flamegraph.pl > cpu.svg

# 経路B: eBPFベース (カーネル内集計、folded形式を直接出力)
sudo profile-bpfcc -F 99 -af 30 > out.folded
flamegraph.pl out.folded > cpu.svg

# スレッドがCPUを手放した(ブロックされた)時間をスタック別に集計
sudo offcputime-bpfcc -df 30 > offcpu.folded
flamegraph.pl --colors=io offcpu.folded > offcpu.svg

# 特定コンテナのPIDを探してそのプロセスのみフィルタ
PID=$(crictl inspect --output go-template \
      --template '{{.info.pid}}' CONTAINER_ID)
sudo bpftrace -e 'tracepoint:syscalls:sys_enter_openat /pid == '$PID'/
  { printf("%s\n", str(args->filename)); }'

# バイナリで追跡可能なシンボルを探す
sudo bpftrace -l 'uprobe:/usr/local/bin/myapp:*' | grep -i order

# 特定関数の遅延ヒストグラム
sudo bpftrace -e '
uprobe:/usr/local/bin/myapp:process_order { @start[tid] = nsecs; }
uretprobe:/usr/local/bin/myapp:process_order /@start[tid]/
  { @latency_us = hist((nsecs - @start[tid]) / 1000);
    delete(@start[tid]); }'

# プロセスのUSDTプローブを一覧
sudo bpftrace -lp $(pgrep -o postgres) 'usdt:*' | head

# PostgreSQLクエリ開始の追跡 (USDTの例)
sudo bpftrace -e 'usdt:/usr/lib/postgresql/16/bin/postgres:query__start
  { printf("query: %s\n", str(arg0)); }'

# ステップ1: 遅延分布の確認 — 本当にディスクが遅いのか、どの程度か?
sudo biolatency-bpfcc -m 5 3

# ステップ2: 犯人プロセス — 誰がIOを生んでいるのか?
sudo biotop-bpfcc 5

# ステップ3: 個別IOの観察 — どのファイル/パターンか?
sudo biosnoop-bpfcc | head -50

# ステップ4: ファイルレベルへ — どのファイルに読み書きが集中しているか?
sudo filetop-bpfcc -C 5

# ステップ5: 書き込みの誘発元を追跡 — ページキャッシュのフラッシュか、直接書き込みか?
sudo bpftrace -e 'tracepoint:block:block_rq_issue
  { @[comm, args->rwbs] = count(); }'

# ステップ1: レイヤの特定 — CPU待ちなのか?
sudo runqlat-bpfcc 5 12     # 1分間に12回: スパイク時点と重なるか

# ステップ2: CPU泥棒を探す — 誰が突然CPUを使うのか?
sudo profile-bpfcc -F 99 -af 30 > spike.folded

# ステップ3: ブロッキングの確認 — オフCPU時間はどこで?
sudo offcputime-bpfcc -df 30 -p $(pgrep -o myapp) > offcpu.folded

# ステップ4: GC/ミューテックス仮説の検証 (例: futex待ち時間の分布)
sudo bpftrace -e '
tracepoint:syscalls:sys_enter_futex { @start[tid] = nsecs; }
tracepoint:syscalls:sys_exit_futex /@start[tid]/
  { @futex_ms = hist((nsecs - @start[tid]) / 1000000);
    delete(@start[tid]); }'

# ステップ1: 接続の寿命を観察 — 閉じられない接続があるか?
sudo tcplife-bpfcc -p $(pgrep -o myapp)

# ステップ2: 生成 vs 終了のバランス — どちら側が漏れているか?
sudo bpftrace -e '
kprobe:tcp_connect { @open[comm] = count(); }
kprobe:tcp_close   { @close[comm] = count(); }
interval:s:10 { print(@open); print(@close);
                clear(@open); clear(@close); }'

# ステップ3: リーク地点のスタック — どこで作られた接続が閉じられないのか?
sudo bpftrace -e 'kprobe:tcp_connect /comm == "myapp"/
  { @[ustack] = count(); }'

# ステップ4: FD増加の一般確認 (ソケットでない可能性もあるため)
sudo opensnoop-bpfcc -p $(pgrep -o myapp) -d 30

sudo bpftrace -e 'kprobe:vfs_read { @ = count(); }
                  interval:s:1 { print(@); clear(@); }'