Ruby Profiler 開発メモ: Safepoint BiasとStackprof
こんにちは。2年間にわたり、やる気が出た時期にドバッとコードを書いては寝かせるのを繰り返してきたプロファイラ開発ですが、最近はドバッとの時期です。この時期になるとプロファイラに対する課題意識がシャープになり、いろいろなアイデアが出てくるので、寝かせる時期が来る前に丁寧めに書き留めておこうとしています。
まずはプロファイラ開発における最大の課題である "正確性" の一端について。
Safepoint Bias
元々の "Safepoint" 自体はプロファイリングとは関係のないJVMの用語で、プログラムの実行の間隙にあり、安全にGCなどを行える瞬間のことを指します。昔のJVMプロファイラはSafepointのタイミングで GetAllStackTraces() を呼び出し、スタックをキャプチャすることで実行の様子を記録していました。
モダンなRubyプロファイラの開祖であるStackprofも似た方式で実装されていました（現在では少し変わっています）。SIGPROFを受けたシグナルハンドラで直接スタックをwalkするのではなく、いわばRubyのSafepointである RUBY_VM_CHECK_INTS() のタイミングまで遅延させて rb_profile_frames() でstack walkをしています。この「遅延」はPostponed Job APIを利用しています。
static rb_postponed_job_handle_t pjob_handle = <pjob のハンドル>;
// RUBY_VM_CHECK_INTS() のタイミングで呼ばれる
void
pjob(void *data)
{
VALUE frames[512];
rb_profile_frames(..., frames, ...); // サンプリング
rb_hash_aset(some_hash, frames); // 保存
}
void
signal_handler(...)
{
// async-signal-safe なことしかしたくないので、
// サンプリングの実行の "予約" に留める
rb_postponed_job_trigger(pjob_handle);
};
この方式はJVMでは "Safepoint Bias" と呼ばれる、強烈な欠点があるとされています。JITされたコードのかたまりの最中にはSafepointは登場しないため、プロファイラの記録がJITコードの始点に偏ってしまうわけです。
翻って、Rubyでは RUBY_VM_CHECK_INTS() はメソッドをexitするたびに走るのでバイアスはかからない…… と思いきや、2つの例外ケースがあります。(1) GVLを手放すメソッド (2) YARVの専用命令にコンパイルされるメソッドです。この2つは古いStackprofでは正確に記録できません。過小に評価されます。
問題1: GVLを手放すメソッド
Postponed Jobの実装の都合、GVLを手放しているメソッドが消費した時間はほとんど計上されない、という問題です。Railsでよく使うものであれば Mysql2#query が該当します。だいたいがI/Oをするメソッドなので、Stackprofで言うところのwall modeのみで起きる問題です。
# このプログラムでは sleep がほとんどの時間を "消費" しているのに
# プロファイルには小さくしか現れない
th = Thread.new { sleep 1 }
100.times do { [1, 2, 3].include?(3) }
th.join
rb_postponed_job_trigger() は、呼び出しの瞬間にEC（execution context; VMの実行状態）を取得しておき、遅延実行される関数に渡してくれます。GVLを持っていないスレッドにSIGPROFが配送されたときも同じことが起こる…… のですが、GVLを持っていないので rb_current_execution_context() はNULLです。
そのケースの実装をよく読むと、 rb_vm_main_ractor_ec() を返すようになっています。つまり、GVLを手放しているメソッドが消費した時間はすべてメインスレッドが消費したことになるわけです。
static rb_execution_context_t *
get_valid_ec(rb_vm_t *vm)
{
rb_execution_context_t *ec = rb_current_execution_context(false);
if (ec == NULL) ec = rb_vm_main_ractor_ec(vm);
return ec;
}
int
rb_postponed_job_register(unsigned int flags, rb_postponed_job_func_t func, void *data)
{
rb_vm_t *vm = GET_VM();
rb_execution_context_t *ec = get_valid_ec(vm);
begin:
switch (postponed_job_register(ec, vm, flags, func, data, MAX_POSTPONED_JOB, vm->postponed_job_index)) {
// ...
}
問題2: YARVの専用命令にコンパイルされるメソッド
opt_plus とかのことです。 CHECK_INTS() が走るタイミングは leave 命令なので、単独のISeqを形成しない String#+ とかはこうなります。
% ruby --dump=insns -e '"2" + "3"'
== disasm: #<ISeq:<main>@-e:1 (1,0)-(1,9)>
0000 putchilledstring "2" ( 1)[Li]
0002 putchilledstring "3"
0004 opt_plus <calldata!mid:+, argc:1, ARGS_SIMPLE>[CcCr]
0006 leave
上述の方式ではopt_plusのタイミングでPostponed Jobが走ることは無いですし、あったとしてもフレームを持たないのでプロファイルに表出することは決してありません。 String#+ なんかは別に無料では全然ないので、気づきにくいながらも意外とイヤな問題です。
解決?
問題1については rb_profile_frames() を遅延実行するのが問題なので、シグナルハンドラの中で直接呼んでしまうことにします。rb_profile_frames() はもともとasync-signal-safeでもないですし、任意のタイミングで割り込みをかけてくるシグナルハンドラの中でのstack walkに耐えるようつくられてはいなかった…… のですが、Ruby 3.2, 3.3の頃にCRubyにパッチが入って安全に呼べるようになりました。（ありがたい）
Stackprofでもそのように改修されています。
しかし問題1のコードをよく見ると、ある瞬間においては Kernel#sleep と Array#include? の両方が記録されるべき瞬間もありそうです。並列（パラレル）に実行されているのだからそれはそうですね。Stackprofには依然この問題はある、と思います。
これを解消するために導入されたのが rb_profile_thread_frames() です。スタックを得るスレッドを確実に指定できるようになったことで、フェアなプロファイリングができる、ということですね。
さて、Pf2ではどうしているかというと……もともとこのAPIを使っていたのですが、あまりにもfragileなトリックが必要（様子1、様子2）で、v0.10.0 以降のC実装ではいったん落としています。より正確で堅牢な実装は考えているので、今後どこかで紹介したいですね。
問題2については完全に未解決です。理屈の上では rb_profile_frames() の中で得られる情報（cfp->pc）だけで opt_plus から Integer#+ なり String#+ なりを呼んでいたことを復元できるはずですが、手元で試している段階です。JITされたらおそらく歯が立ちません。
歯切れ悪めですが、大きな課題意識について紹介できたところで終わります。