プロファイリング
Brendan Gregg の Flame Graphs と Off-CPU Analysis を取得して読み、 理解した内容を自分の言葉で書いたもの。本文の引用はしていない。
性能を測るがどの資源が詰まっているかなら、 こちらはどのコード経路がその時間を使っているか。
USE メソッドの限界に書いたとおり、 「どの資源が詰まっているか」と「なぜこのリクエストが遅いか」は別の問いで、 後者に答えるのがここ。出典も同じ Brendan Gregg。
待っている時間は CPU プロファイルに映らない
最初に押さえるのはこれ。
tar の実測例が分かりやすい。
経過時間 50.8秒
CPU 時間 12.6秒
差 38.2秒 ← ストレージ I/O で待っていた
CPU プロファイルを取っても、この38.2秒は1サンプルも現れない。 CPU を使っていないので、当然サンプルされない。
CPU プロファイルが取り逃すもの。
I/O 待ち(ディスク、ネットワーク)
ロック競合(ミューテックス、セマフォ)
実行キューでの待ち(CPU が飽和しているときの順番待ち)
ページング、スワップ、メモリのストール
タイマーによるスリープ、条件変数の待ち
スレッドの状態は2つしかない。
| 状態 | |
|---|---|
| on-CPU | プロセッサで命令を実行している |
| off-CPU | ブロックされていて動いていない |
両方を見て初めて、スレッドの時間の100%が説明できる。 片方だけでは、必ず説明のつかない時間が残る。
フレームグラフの読み方
最も多い誤読が x 軸。
x 軸はスタックの母集団をアルファベット順に並べたもので、時間の経過ではない。
左から右へ処理が進むように見えるが、そうではない。
アルファベット順である理由は、そう並べると同じフレームが最大限まとまり、 プロファイル全体の姿が見えるようになるから。
| 軸・要素 | 意味 |
|---|---|
| y 軸 | スタックの深さ。下が 0 で上へ積む。上端が、そのとき実行中のコード |
| 箱の幅 | そのフレームがスタックに現れた頻度。 広いほど頻繁 |
| 色 | 既定ではランダム。隣り合うフレームを見分けるためだけで、意味を持たない |
色が「炎」なのは、CPU が「熱い」(忙しい)ことの説明に使えたからで、 暖色そのものに情報はない。
種類がいくつかある。
CPU CPU を消費しているスタック
メモリ サンプル数ではなくバイト数。慣例として緑にして種類を区別する
off-CPU ブロックしている時間
hot/cold 頻度の高い経路と低い経路を分ける
差分 2つのプロファイルを比較する。回帰の調査に使う
差分フレームグラフが、性能の回帰を追うときに効く。 パフォーマンス予算を超えたとき、 「何が増えたか」を直接見られる。
サンプリングであることの含み
CPU フレームグラフは一定間隔でスタックを採取して作る。
もともとは全関数を追跡していたが、やめた理由が2つある。
追跡のオーバーヘッドが高すぎて、対象そのものを歪めた
数秒ぶんを可視化すると密すぎて読めなかった
だからサンプリングには隙間がある。 すべての呼び出しを捉えるわけではない。 統計的な絵として読む。
スタックが取れないと何も始まらない
難しいのはフレームグラフを描くことではなく、意味のあるスタックを得ること。
-fomit-frame-pointer でビルドしない(フレームポインタを残す)
Java は -XX:+PreserveFramePointer。JIT の記号は別途手当てが要る
これらがないと、スタックが16進数のまま出てきて、何も分からない。
off-CPU をどう測るか
カーネルのスケジューラのコンテキストスイッチを計装する(Linux なら finish_task_switch())。
ここに気の利いた前提がある。
off-CPU のあいだ、アプリケーションのスタックは変わらない。
だから計装点は1つでよい。 スレッドが再開した瞬間に、 その時点のタイムスタンプ・ブロックしていた時間・ユーザーとカーネルのスタックが まとめて取れる。ブロックに入るところを別に捕まえる必要がない。
サンプリングでも一応できるが、数万のスレッドを常時サンプルすることになるので、 イベント駆動の追跡に比べてはるかに重い。
off-CPU 分析の3つの落とし穴
1. オーバーヘッド
スケジューラのイベントは、極端な場合秒間100万件に達する。実測がある。
8 CPU、秒間 102,000 コンテキストスイッチ
perf でイベントを書き出す スループット 9% 低下、10秒で 224 MB、後処理 35秒
eBPF でカーネル内で集約 スループット 6% 低下、後処理 6秒
カーネル内で集約する方を選ぶ。 書き出す量が桁違いに減る。
手順として、0.1秒のような短い採取から始めて、少しずつ伸ばす。
事前に vmstat の cs 列でスイッチの頻度を見ておく。
2. アイドルの待ちが出力を埋める
ここが実務で最も効く注意。
Web サーバーのスレッドプールは、リクエストを待ってソケットでブロックしている。 この待ちは長いので、素直に集計するとoff-CPU の出力を支配する。
そしてそれは利用者の遅延とは何の関係もない。 本当に見たい遅延が、その下に埋もれる。
対処は、リクエストと同期している文脈だけに絞ること。
MySQL なら、do_command() の中でクエリを処理しているあいだの off-CPU 時間だけを取る。
仕事を待っている背景スレッドは除く。
絞り方は、スタックの文字列で後処理するか、 アプリ側の関数を計装してカーネルの追跡を出し入れするか。
3. 非自発的なコンテキストスイッチ
カーネルが実行中のスレッドを横取りした場合(Linux では TASK_RUNNING)、
出てくるスタックに意味がない。 そこでブロックしたわけではないため。
offcputime の --state で状態を絞る。
1 TASK_INTERRUPTIBLE 割り込み可能な待ち
2 TASK_UNINTERRUPTIBLE 割り込み不可の待ち(多くは I/O)
両方を1枚にする
on-CPU と off-CPU のスタックを両方集めて、スレッドの時間すべてを見る。
フレームグラフはこれを1枚に収められる。 そうすると、遅さが「計算しているから」なのか「待っているから」なのかが 同じ絵の中で判別できる。
この2つは対立せず補完し合う。 片方だけ取って結論を出さない。
このリポジトリの他の場所との関係
| ここでの話 | 対応する場所 |
|---|---|
| 実行キューでの待ちが off-CPU に出る | 性能を測る — USE の飽和(Saturation) |
| 飽和すると待ちが支配的になる | 分散システム — executor load average を見る理由 |
| 差分で回帰を見つける | パフォーマンス予算 — 予算を超えたときに何が増えたか |
| 推測せず、実際に取ってから直す | 原則 |