Dev Study
← 性能分析の土台
レッスン 5 / 10·約 9 分·第13期 性能分析

写っていないことは、起きていない証拠ではない

リクエストがアプリケーションに届くまで
  1. ブラウザURL入力
  2. DNS名前→IP
  3. ルータ経路選択
  4. ロードバランサ振り分け
  5. Nginx受け口
  6. アプリ処理今ここ
  7. DB保存

前回まで数字の読み方と観測の費用を見てきました。今回は同じ観測器を分解能の側から見ます。

まず結論

サンプリング型のプロファイラは一定の間隔で覗くだけなので、間隔より短い事象は確率でしか写りません。名前が出ない関数は、速いのではなく、覗いた瞬間に走っていなかっただけかもしれません。

つまりサンプリングの結果は「無い」ことの証拠になりません。同じプログラムを同じ条件で測っても、出る回と出ない回が混ざります。

? 読む前に予測

決定的な計時器では実行時間の約7%を占める関数を、サンプリング型のプロファイラで測るとどうなるでしょうか。

当てることが目的ではありません。外した予測ほど記憶に残るので、直感で選んでください。

抽象原理

覗いた瞬間に走っていたものしか、記録に残らない

性能の道具には2つの原理があります。1つは全部数える方式で、関数の出入りのたびに記録を足します。もう1つがサンプリングで、一定の間隔で「いま何を実行しているか」だけを見ます。覗いた瞬間に走っていなかったものは記録に残りません。

1回0.7ミリ秒で終わる処理を、10ミリ秒ごとの断面で捉えるとします。断面の間に始まって終われば、その処理は無かったことになります。何度も呼ばれていれば重なる見込みはありますが、重なるかは確率の問題です。

ここが分かれ目です。決定的な方式の「0回」は、呼ばれていないことを意味します。しかしサンプリングの「0サンプル」は、呼ばれていないのか写らなかったのかを区別できません。同じゼロでも、支えられる主張の強さが違います。

具体実物

全体の6.70%を占める関数が、12回中4回消えた

実際に消えるところを作りました。Python で小さなサンプリングプロファイラを書き、別スレッドから一定間隔で実行位置を覗かせます(同じ原理の再現で、perf は使っていません)。

仕掛けは2つの関数です。rare_spike は1回およそ0.73ミリ秒で30回、bulk は1回およそ5.1ミリ秒で60回呼ばれます。決定的な計時器で測ると rare_spike は全体の6.70%、確かにそこにある大きさです。

同じ作業を12回ずつ測った結果(Docker Desktop の Linux VM / aarch64 / Python 3.11.2)コマンド出力
GROUND TRUTH (deterministic timing, same call counts as the workload)
rare_spike: 30 calls, 21.9 ms total, 0.732 ms each
bulk      : 60 calls, 305.9 ms total, 5.098 ms each
rare_spike is 6.70% of the run -- it IS there, and it IS measurable
 
SAMPLING at interval 10 ms (100 Hz), 12 independent runs of the SAME workload
rare_spike sample counts per run: [2, 0, 2, 1, 2, 1, 0, 1, 1, 2, 0, 0]
runs where rare_spike got ZERO samples (invisible): 4/12
mean samples/run: 1.00
 
SAMPLING at interval 1 ms (1000 Hz), 12 independent runs of the SAME workload
rare_spike sample counts per run: [1, 1, 4, 1, 1, 0, 0, 6, 0, 1, 2, 2]
runs where rare_spike got ZERO samples (invisible): 3/12
mean samples/run: 1.58

同じプログラム、同じ回数、同じ環境です。それでも 100 Hz の行には 0 が4つ並びます。この4回のプロファイルだけを見た人は、rare_spike は問題ではないと結論します。

ただし 1000 Hz の行を「周期を10倍にしても消えた」と読んではいけません。合計 21.9 ミリ秒の rare_spike なら、公称どおりの期待サンプル数は約2.2と約22。実測の平均 1.00 と 1.58 から逆算した実効の頻度は約46 Hz と約72 Hz です。この2行は 1000 Hz と 100 Hz の比較になっていません。 本当に1ミリ秒ごとに覗けば、0.732ミリ秒の呼び出し30回を全部取り逃す確率は、各回独立とみなして (1−0.732)^30 ≈ 7×10^-18 です。公称の周期は設定であって、覗いた回数の測定値ではありません。

✓ ここまでの確認

プロファイルに名前が出なかった関数について、言えることはどれですか。

抽象原理

ゼロは、反証に使えない

一般の形に引き上げます。観測器には必ず分解能があり、それより細かいものは通り抜けます。その観測器から出た「無かった」は主張を否定する材料になりません。

アルゴリズム編『桁で見積もってから測る』で、プロファイルは写真であって傾きではない、と見ました。今回の差分は時間軸ではなく分解能で、写真の解像度より小さいものは何枚撮っても写りません。

だから報告を読むときの問いは2段です。上位に出ているものは本当に大きいか。そして出ていないものは本当に小さいのか。2番目に答えるには観測器の条件が要りますが、それは資料にあるとは限りません。

具体実物

対照実験 — 毎回写る代わりに、1.55倍遅くなった

同じ作業を、全部数える方式(cProfile)でも測りました。

cProfile で同じ作業を測る(同じ環境)コマンド出力
uninstrumented run : 315.7 ms
under cProfile     : 488.7 ms   -> 1.55x slower (the cost of measuring)
 
  ncalls  tottime  percall  cumtime  percall filename:lineno(function)
  60    0.455    0.008    0.455    0.008 /tmp/cp.py:8(bulk)
  30    0.033    0.001    0.033    0.001 /tmp/cp.py:4(rare_spike)

rare_spike は ncalls=30 で毎回出ます。1つずつ数えているので消えようがありません。代わりに同じ作業が 315.7 ミリ秒から 488.7 ミリ秒へ、この試行で 1.55倍に伸びました。3本目で見た「測ることが対象を変える」が値として出ています。

⇄ 2つを見比べる
具体例 A

サンプリング型のプロファイラ

一定の間隔で実行位置を覗き、断面を集計します。断面の間で終わった処理は残らず、繰り返してもゼロの回が混ざります。間隔を細かくすれば写る確率は上がりますが、覗く回数の分だけ費用を払います。

同じ関数の見え方(この環境の12回試行)表
方式                     取りこぼし       払う費用
100 Hz サンプラ          12回中4回ゼロ    小さい
公称1000 Hz(実効約72 Hz) 12回中3回ゼロ    覗く回数ぶん増える
cProfile(全数)           ゼロの回なし     この試行で1.55倍
具体例 B

パケットキャプチャで再送を探す

受信側で通信を記録し、再送が現れるかを見ます。本教材の検証では3回続けて0件でした。落ちたパケットは受信側に届かず、数え方も完全一致する区間に絞っていたためです。記録の側には再送が起きていないように見えます。

同じ現象を2つの手段で見る表
観測手段            再送の見え方      性質
受信側のキャプチャ   3回続けて0件      置き場所と数え方の外は残らない
カーネルのカウンタ   累計として増える  数え続けている

プロファイラの取りこぼしと、キャプチャに再送が写らないこと。道具も層も違いますが、共通する構造は何でしょうか。

それぞれの観測器が「何を」記録できるか — 常に数えるのか、ある瞬間・ある場所・ある条件に合うものだけを見るのか — を比べてみてください。

✓ ここまでの確認

サンプリング周期を細かくすると、短い事象の取りこぼしはどうなりますか。

抽象原理

図で見る — 断面と、断面の間

同じ実行を、2つの原理で見る
実際の実行短い処理が何度か走る
計時では6.70%
一定間隔で覗く(断面を集める)
断面に重なったサンプルが付く
上位に出る
断面の間で終わった残らない
この回はゼロ
出入りを全部数える
毎回 ncalls に載るゼロの回が無い
実行は伸びる
だから
ゼロの読み方無かった、ではなく、写らなかった
  • ・周期を細かくすると重なる確率は上がる。ただし公称の周期どおりに覗けているかは、別に確かめる
  • ・横軸がサンプル数であって時間ではないことは、図解コース「フレームグラフの読み方 — 横軸は時間ではない」が扱っています

この章のまとめ

  • サンプリング型は一定間隔の断面を集めるので、間隔より短い事象は確率でしか写らない。
  • 実測では、全体の6.70%を占める関数が12回中4回で1サンプルも出なかった(Docker Desktop の Linux VM の値。一般則ではない)。公称1000 Hz の行は実効で約72 Hz で、周期を10倍にした比較になっていない。公称の周期は、覗いた頻度の測定値ではない。
  • 全数を数える方式は毎回捉える代わりに費用を払い、この試行では1.55倍に伸びた。
  • サンプリングのゼロは反証に使えない。次の一手は原理の違う観測手段を足すこと。
  • perf record の -F の既定値は man page に記載が無い。観測器の条件は自分の環境で読む。

自分の現場で確かめる

読んだだけでは身につきません。手元の環境で実際に見てみてください。

環境:

理解度チェック

読んだ直後は「分かった」と感じやすいものです。実際に解いて確かめてください。

問題 1 / 3正解: 0

サンプリング型と、呼び出しを全部数える決定的な型。違いとして正確なのはどれですか。

用語集(5語)
サンプリング(標本抽出)型のプロファイラ
一定の間隔で実行位置を覗き、断面を集めて集計する方式。費用は小さいが、間隔より短い事象は確率でしか写らない。
決定的(deterministic)なプロファイラ
関数の出入りをすべて記録する方式。取りこぼさない代わりに記録の費用が実行時間に乗る。cProfile がこの型。
分解能
その観測器が区別できる最小の粒。周期10ミリ秒のサンプラは、1回1ミリ秒未満の処理を確実には捉えられない。
反証不能
その観測結果では主張の誤りを示せない状態。サンプル数がゼロでも「その処理が無い」とは示せない。
kernel.perf_event_max_sample_rate
許される最大サンプリング周波数を持つ Linux の sysctl。-F max はこの値まで上げると man にある。環境依存。

出典(一次ソース)