ハードウェア上級 #2 eBPF 観測 — 平均が隠すテールを見る

読了 8分

第 1 編perf はサンプリングツールでした。毎秒数千回 CPU の現在位置を撮って「時間がどこに使われているか」の統計的な絵を描きました。今回の eBPF はアプローチが違います。カーネル内のイベントが起きる通り道に小さなプログラムを仕掛けておき、イベントが起きるたびに直接記録します。サンプリングが風景写真なら、eBPF は通り道の通行記録です。ディスク I/O 一件一件の遅延、プロセスが CPU を受け取るまで待った時間の一件一件がすべて捕捉されます。

この違いが重要な理由は、運用で本当に痛い問題が平均ではなくテールにあるからです。

平均が隠すもの — 分布とテールレイテンシ #

中級 #1 で扱った %wa とロードアベレージは良い出発点ですが、どちらも平均です。平均は分布をつぶしてしまいます。

ディスク I/O 1,000 件のうち 990 件が 0.2ms、10 件が 200ms かかったとします。平均は約 2.2ms で問題なさそうに見えます。しかしユーザーリクエスト 1 つが I/O を数十回起こすなら、かなりの数のリクエストがあの遅い 10 件のどれかを踏みます。ユーザーが体感する「ときどき一瞬止まる」の正体が、このテールレイテンシ (tail latency、分布の端にある少数の遅いイベント) です。平均と使用率の指標ではこのテールは見えません。分布全体、つまりヒストグラムが必要です。

eBPF がこの仕事に合う道具である理由は、すべてのイベントをカーネル内で集計できるからです。イベントごとにユーザー空間へデータを運び出すとコストが大きいですが、カーネル内でヒストグラムとして累積しておき、終わるときに要約だけ持ってくればコストは小さくて済みます。

eBPF — カーネル内で動く小さなプログラム #

eBPF (extended Berkeley Packet Filter) は名前のとおりパケットフィルターから出発しましたが、いまは カーネル内で安全に実行される汎用ミニプログラム の実行環境です。システムコールの進入、ディスク I/O の完了、スケジューラのタスク切り替えのようなカーネルイベントにプログラムを取り付けておくと、そのイベントが起きるたびにプログラムが動いて時刻を測り、カウンターを増やします。

「カーネル内で任意のコードを動かす」という話が危険に聞こえるなら正常です。同じことをカーネルモジュールでやれば、バグ 1 つがカーネルパニックにつながります。eBPF が違うのは検証器 (verifier) です。プログラムをカーネルにロードする前に検証器がすべての実行経路を検査し、終わらない可能性のあるループ、許可されていないメモリアクセス、上限を超えるサイズのプログラムをすべて拒否します。検証を通過したプログラムだけが実行されるため、eBPF トレーシングツールがカーネルを落とすことは構造的に防がれています。

eBPF を直接書くことはまれです。運用者は普通 2 層のツールを使います。即席の質問には bpftrace、定型化された分析には BCC ツール集です。

bpftrace — 1 行で投げる質問 #

bpftrace は eBPF プログラムを 1 行のスクリプトとして書けるようにするツールです。「イベント /条件/ { 動作 }」という形です。

bpftrace ワンライナー — ファイルオープンの追跡
# いまこのサーバーでどのプロセスがどのファイルを開いているかをリアルタイム出力
$ sudo bpftrace -e 'tracepoint:syscalls:sys_enter_openat { printf("%s %s\n", comm, str(args->filename)); }'
nginx /var/log/nginx/access.log
postgres /var/lib/pgsql/data/base/16384/2619

tracepoint:syscalls:sys_enter_openat が仕掛けておくイベントで、波かっこの中がイベントごとに実行する動作です。同じ文法でヒストグラムも 1 行です。

bpftrace ワンライナー — read サイズの分布
# read() が返したバイト数の分布をカーネル内で集計
$ sudo bpftrace -e 'tracepoint:syscalls:sys_exit_read /args->ret > 0/ { @bytes = hist(args->ret); }'

Ctrl-C で終了すると、それまで累積されたヒストグラムが出力されます。この「終わるときに要約だけ受け取る」形が eBPF 観測の基本形です。

biolatency — ブロック I/O 遅延の分布を読む #

BCC の biolatency はブロックデバイス I/O 一件一件の遅延を測ってヒストグラムで見せてくれます。10 秒間に 1 回集計した例です。

biolatency 10 1
$ sudo biolatency 10 1
Tracing block device I/O... Hit Ctrl-C to end.

     usecs               : count     distribution
        64 -> 127        : 9        |*                                       |
       128 -> 255        : 156      |**********************                  |
       256 -> 511        : 274      |****************************************|
       512 -> 1023       : 92       |*************                           |
      1024 -> 2047       : 18       |**                                      |
     32768 -> 65535      : 5        |                                        |
     65536 -> 131071     : 4        |                                        |

区間は 2 倍ずつ大きくなる対数スケールです。読む順序は 2 つです。

  • 本体がどこにあるか — 大部分の I/O が 128〜511us に集まっています。SSD なら正常範囲です。
  • テールがあるか — 65〜131ms の区間に 4 件あります。本体より数百倍遅い I/O です。iostat の平均遅延 (await) では本体に埋もれて見えなかったものが、ヒストグラムでは離れた山として現れます。このテールの原因候補が SSD 内部のガベージコレクション、書き込みキャッシュのフラッシュ、他のワークロードとのキュー競合のようなもので、そこからが本当の分析の始まりです。

平均という 1 つの数字だったら「ディスクは問題ない」で閉じていた事件が、分布では「990 件は問題なく 4 件がおかしい」という追跡可能な手がかりに変わります。

runqlat — CPU を受け取るまで待った時間 #

CPU 使用率は 50% なのにアプリケーションが遅いサーバーがあります。このとき見るべきなのがスケジューラ待ちです。実行準備が終わったタスクが実行キュー (run queue) で CPU を割り当てられるまで待った時間で、BCC の runqlat がこの分布を見せてくれます。

runqlat 10 1
     usecs               : count     distribution
         0 -> 1          : 1306     |**********************                  |
         2 -> 3          : 2342     |****************************************|
         4 -> 7          : 1217     |*********************                   |
      8192 -> 16383      : 41       |                                        |
     16384 -> 32767      : 23       |                                        |

大部分は数 us 以内に CPU を受け取りますが、テールでは 8〜32ms 待ったタスクが 60 件以上見えます。使用率が低いのにこうしたテールが生まれる典型的な原因は、コンテナの CPU 制限 (cgroup クォータを使い切ると次の周期まで強制待機)、特定コアへのタスクの偏り、短いバーストの同時到着です。中級 #1 のロードアベレージが「列がある」までを教えてくれたとすれば、runqlatその列が各タスクを実際に何 ms 待たせたのか を教えてくれます。

BCC ツールの地図 #

BCC にはこの種の単一目的ツールが数十個あります。よく使うものだけ絞ると次のとおりです。

ツール見せてくれるもの
execsnoop新しく実行されるプロセスすべて。短命プロセスの暴走を捕まえます
opensnoopファイルオープンすべて。設定ファイルをどこから読んでいるかの追跡にも役立ちます
biolatency / biosnoopブロック I/O 遅延のヒストグラム / 一件ごとの詳細
runqlatスケジューラ待ち時間の分布
ext4slowerしきい値より遅いファイルシステム操作だけ選んで出力 (XFS などの変種もあります)
cachestatページキャッシュのヒット率
tcplifeTCP 接続の寿命と送受信量。接続単位の要約です
tcpretransTCP 再送の発生瞬間と対象

ツール名の規則が見えてきます。-snoop はイベントを一件ずつ流して見せ、-lat は遅延ヒストグラムを集計し、-slower は遅いものだけ濾し取ります。新しいツールに出会っても名前から動作を推測できます。

オーバーヘッドと運用の注意 #

eBPF は軽いですが、ただではありません。コストはイベント頻度に比例します。

  • イベント頻度を先に考えますexecsnoop が仕掛けるプロセス実行は毎秒数十件のレベルなので負担になりませんが、runqlat が仕掛けるスケジューラ切り替えは毎秒数十万件になり得ます。忙しいサーバーで数 % レベルの CPU を余計に使い得るという意味なので、負荷が深刻な瞬間には測定自体が負荷になるという点を覚えておきます。
  • 集計型ツールのほうが一件ごとの出力より安く済みます。ヒストグラムはカーネル内にとどまり、要約だけが渡ってきます。同じイベントでも biosnoop (一件ごと) より biolatency (集計) のほうが負担が小さいです。
  • 診断ツールと常時モニタリングを区別します。この記事のツールは問題が見えたときに点けて、答えが得られたら消す用途です。常時収集が必要なら、eBPF ベースのモニタリングエージェントを別途検討するほうが適切です。
  • カーネルバージョンと権限の前提があります。比較的新しいカーネル (RHEL 8、Ubuntu 18.04 以降のレベル) と root 権限が必要です。検証器のおかげでカーネルが落ちることはありませんが、古いカーネルではツールがそもそもロードできないことがあります。

まとめ #

今回つかんだ絵です。

  • %wa やロードアベレージのような平均指標は分布をつぶします。体感品質を削るテールレイテンシはヒストグラムでしか見えません。
  • eBPF はカーネルイベントに仕掛けておく小さなプログラムで、検証器が安全を保証し、カーネル内集計のおかげでコストが小さいです。
  • biolatency でブロック I/O の本体とテールを切り分け、runqlat で使用率が低いのに遅いサーバーのスケジューラ待ちを確認します。
  • 即席の質問は bpftrace ワンライナー、定型分析は BCC ツールで投げ、イベント頻度と集計の有無でオーバーヘッドを見積もります。

次回 — メモリ深掘り #

次の記事「ハードウェア上級 #3 メモリ深掘り」では 2 番目のリソースに入っていきます。仮想メモリとページテーブル、TLB ミスのコスト、ページ回収とキャッシュの綱引きまで、使用量グラフの裏でメモリが実際にどう動いているのかを扱います。

X