トレースとデバッグ

リクエストが遅い場合、その原因は CPU、ランキュー、ロック、またはデバイスにある可能性がある。トレースでは、まず測定対象とその開始・終了の境界を特定し、仮説を検証するのに十分なイベントを収集する必要がある。

1. 問題と測定対象の特定

同じ「リクエストの所要時間」でも、アプリケーションのキュー待ち、システムコール、ブロック層のキュー待ち、デバイス処理が含まれることがある。イベントのネストや並列関係が明確でない限り、異なる層のレイテンシを単純に足し合わせることはできない。

2. ftrace と tracefs

最新の tracefs は通常 /sys/kernel/tracing にマウントされるが、旧パス /sys/kernel/debug/tracing が残っている場合もある。available_tracers は現在利用可能なトレーサーをリストし、available_filter_functions は追跡可能な関数をリストする。設定によって見える内容は変化する。

cat /sys/kernel/tracing/available_tracers
cat /sys/kernel/tracing/events/sched/sched_switch/format

これらの読み取り専用コマンドは、まず能力とフィールドを確認するために使用する。読み取りに失敗したからといって、関数が存在しないとは即座に判断してはならない。function や function_graph を有効にするとトレース状態が変更されるため、実際の収集には独立した trace instance を使用し、フィルタリング範囲とバッファを設定してから収集を開始し、終了後に無効化してクリーンアップするのが望ましい。

• function は選択された関数のエントリを記録する。フィルタなしで全量を有効にすると、大量のイベントが発生する可能性がある。
• function_graph は関数のエントリとリターンを関連付け、呼び出し階層と持続時間を表示する。スケジューリングによって実行が中断された時間をカウントするかどうかは、トレーサーのオプションに依存する。
• trace はフォーマットされたバッファビューを提供する。trace_pipe は消費型の読み取りであり、複数のリーダーがイベントを競合するため、互いに影響を受けないブロードキャストログとして扱うことはできない。

CPU バッファは記録を上書きしたり、欠落させたりする可能性がある。CPU 間で比較を行う場合、trace_clock の理解も必要である。trace instance は複数の収集設定を分離できるが、動的プローブ定義などのリソースは共有されるため、相互に影響を与える可能性がある。インターフェースとオプションについては ftrace ドキュメント を参照。

動的 ftrace は kprobe event とは異なる

動的 ftrace は、トレース可能な関数の挿入ポイントのオン/オフによって関数トレースを有効/無効にする。kprobe_events や dynamic_events への登録は動的プローブイベントであり、別のメカニズムに属する。state+0x12(%di) のような固定オフセット式を読み取るには、アーキテクチャ、関数シグネチャ、構造体レイアウトの一致を同時に確認する必要があり、一般的な TCP 状態の読み取り例として安易に使用してはならない。

適切な tracepoint があるかどうかを優先して確認し、動的関数プローブが確実に必要な場合に限り、対象のシンボル、BTF/DWARF、実際のソースコードと組み合わせて引数を解釈する。kprobe events を参照。

3. perf：カウントとサンプリングは異なる問いに答える

perf stat はカウントを集計し、perf record はイベント発生に応じてサンプルを記録し、perf report はサンプルを集計する。スリープ中のプロセスの cycles を記録しても、それはマシン全体の 10 秒間の CPU ハットスポット（ホットスポット）を代表するものではない。

# マシン全体ではなく、このコマンドとその継承範囲を測定する。
perf stat -e cycles,instructions,cache-misses -- ./workload

# 実際のワークロードの呼び出しスタックを記録する。DWARF 展開には追加のオーバーヘッドがある。
perf record -e cycles -g --call-graph dwarf -- ./workload
perf report

# 問題が本当にマシン全体のホットスポットである場合、システム全体のサンプリングを明示的に使用する。
perf record -a -e cycles -g -- sleep 10

./workload は測定対象のプログラムを表し、実際のコマンドに置き換える必要がある。権限、PMU、仮想化、プラットフォームの能力がイベントの利用可否を決定する。cache-misses などの一般的な名前は、異なる CPU では必ずしも同じハードウェアの意味に対応するわけではない。

イベントが多すぎて多重化（multiplexing）が発生した場合、実行時間の割合とスケーリング結果を確認する必要がある。呼び出しスタックの品質は、フレームポインタ、DWARF、シンボル、展開方法に依存する。シンボルの欠落、サンプルの欠落、誤った展開は、ホットスポット図を変更する可能性がある。サンプルのパーセンテージは、現在のイベントと記録範囲に対する比率であり、任意の関数の正確なウォールクロック時間ではない。ツールのセマンティクスについては perf stat および perf record を参照。

4. レイテンシヒストグラムの正しい構築

hist(nsecs) はタイムスタンプの分布を示すものであり、操作のレイテンシを示すものではない。以下に、bpftrace 0.24 を例として、指定されたプロセスが収集期間中に完全に発生させた write システムコールを記録し、TID を使用してエントリとエグジットを関連付ける方法を示す。

まず、対象の tracepoint とフィールドが存在することを確認する。

bpftrace -lv 'tracepoint:syscalls:sys_enter_write'
bpftrace -lv 'tracepoint:syscalls:sys_exit_write'

write-latency.bt として保存する。

tracepoint:syscalls:sys_enter_write
/pid == $1/
{
    @start[tid] = nsecs(monotonic);
}

tracepoint:syscalls:sys_exit_write
/pid == $1 && @start[tid]/
{
    @lat_us = hist((nsecs(monotonic) - @start[tid]) / 1000);
    @returns[args->ret < 0] = count();
    delete(@start, tid);
}

interval:s:10
{
    exit();
}

END
{
    clear(@start);
}

bpftrace write-latency.bt 12345

12345 を測定対象のプロセス PID に置き換える。@returns[0] は負でない戻り値、@returns[1] は負の戻り値を表す。正の値は短書き（short write）の可能性もあり、そのまま「完全なビジネス成功」と呼ぶことはできない。時間単位はマイクロ秒であり、10000 マイクロ秒は 10 ミリ秒である。

この測定には、syscall 中のブロックとスケジューリング待機が含まれるため、デバイス完了のレイテンシとは等しくない。例えば、ファイルへの write が返された後でも、データはページキャッシュに残っている可能性がある。また、writev、io_uring などの他の書き込みパスはカバーされない。収集開始前にエントリしていた呼び出しや、終了時にまだ返されていない呼び出しは完全なサンプルに含まれないため、ロングテール分析ではこのような切り捨てを考慮する必要がある。

身元の関連付け：同期 syscall と非同期リクエストは別々に設計

TID は通常の同期 syscall のエントリとエグジットを関連付けるのに十分だが、非同期 I/O リクエストはスレッドや割り込みを跨いで完了するため、真のリクエスト ID を使用し、再利用、マージ、リトライ、クリーンアップを処理する必要がある。汎用の再帰関数をトレースする場合、ネストの深さを区別する必要があり、単一の start[tid] をそのままコピーしてはならない。言語と時刻のインターフェースについては bpftrace 0.24 標準ライブラリ を参照。

同じスレッドから 2 つの重複するリクエストを発行し、完了スレッドを選択する。2 つの関連付け方法は同じイベントを同時に処理するが、誤った関連付けで正の数が算出されたとしても、それがそのリクエストの真のレイテンシであるとは限らない。

5. 集計、欠落、オーバーヘッド

イベントごとの printf は、ユーザー空間の出力をボトルネックにする可能性がある。分布のみが必要な場合は、カーネル側で count/hist/sum の集計を優先し、詳細が必要な場合は、サンプリング、フィルタリング、バッファ容量、欠落カウントを明確にする。

欠落を記録し、残存エントリをクリーンアップする必要がある。次のリクエストが古いタイムスタンプを継承しないようにする。

BCC には多くの既存ツールがあるが、従来の BCC ワークフローは通常、実行時に BPF をコンパイルするため、固定されたプリコンパイル済み CO-RE バイナリのセットではない。biolatency、runqlat、tcpretrans などの名前は用途の大まかな説明であり、正確な測定には開始点と終了点、フィルタ条件をインストールされたバージョンで確認する必要がある。BCC プロジェクト を参照。

6. ログ、動的デバッグ、障害ダンプ

printk のログレベルは記録される重大性の分類に影響し、コンソール閾値はどの記録をコンソールに出力するかを決定するが、他のレベルの記録がログリングから消えるわけではない。実際の KERN_* マクロエンコーディングにはカーネルヘッダーファイルを使用し、読みやすい <0> の表示形式を現在のマクロ定義として偽装してはならない。

dynamic debug は、コンパイル時に該当するメカニズムに組み込まれた pr_debug() / dev_dbg() などの呼び出しポイントのみを制御する。関数名で検索してエントリがないからといって、その関数が実行されていないわけではない。その関数に該当するデバッグ呼び出しポイントがない可能性がある。インターフェースは /proc/dynamic_debug/control または debugfs にあり、設定による。

kdump には crashkernel メモリの予約、キャプチャカーネル、initramfs、保存パスの準備が必要である。クラッシュ後、キャプチャカーネルに切り替わり、元のメモリは /proc/vmcore などのインターフェースを通じてエクスポートされ、ユーザー空間ツールによって保存またはフィルタリングされる。kexec -p を実行しただけで、次回必ず完全で読み可能なダンプが取得できるとは限らない。デバイス状態とキャプチャ環境もサポートしている必要がある。

ダンプ分析：シンボルはクラッシュ時のカーネルと一致させる必要がある

分析時には、現在の uname -r を機械的に適用するのではなく、⁠クラッシュしたカーネルと一致する vmlinux、デバッグシンボル、および必要なモジュールを使用する。マシンはすでに別のバージョンに再起動している可能性がある。crash ユーティリティでは、bt は通常、現在の/指定されたタスクのバックトレースを表示し、foreach bt がタスクごとのバックトレースを行う。kdump および crash ヘルプ を参照。

KGDB はブレークポイントの設定、レジスタの読み取り、ステップ実行が可能だが、実行を一時停止すると時間動作が変化するため、ブレークポイントの結果から真のレイテンシを直接推論するには適さない。接続トランスポート、カーネル設定、シンボルも一致させる必要がある。設定と例については ビルドと開発ディレクトリ を参照。

7. 解釈可能な診断フローの例

1. シナリオの固定。 リクエスト、時間窓、負荷、レイテンシの境界を記録する。
2. 方向の絞り込み。 カウントまたはサンプリングを使用して、on-CPU と待機を区別する。
3. 仮説の検証。 少数のイベントを選択し、必要に応じて関連する関数パスを深く調べる。
4. 観測の影響確認。 有効化前後のスループット、レイテンシ、欠落状況を比較する。
5. 解釈条件の保持。 ツールバージョン、設定、フィルタ、測定制限を記録する。

各ステップは、単にログ量を増やすのではなく、不確実性を絞り込むべきである。

関連リンク：eBPF 基礎、プログラムタイプ、ユーザー空間での ftrace と bpftrace の実践。