Ruby用の新しいプロファイラ "Pf2" を開発しています & 2年の振り返り
こんにちは osyoyu です。近況です。
ここ2年ほど、Ruby用のプロファイラである "Pf2" というツールを開発しています。RubyKaigi 2024の発表などをお聞きいただいた方はご存知かもしれません。この記事では、使い方や特徴を簡単に紹介するとともに、開発の経緯や様子を振り返ろうと思います。
プロファイラにもさまざまな種類がありますが、Pf2はCPUプロファイラと呼ばれるジャンルに属します。あるコードがCPUをどれだけ使用したか、を計測することに特化しています。
何ができるか・使い方
新機能の情報はないので、ご存知の方は読み飛ばしていただいてかまいません。
Pf2がどんなツールかを簡単に説明します。計測したいRubyコードを Pf2.profile で囲むと、戻り値としてプロファイル結果が得られます。
require 'pf2'
class UsersController
def show
profile = Pf2.profile do
@users = User.find_by(params[:id])
render "index"
end
File.binwrite("tmp/profile.pf2prof", Marshal.dump(profile))
end
end
この結果を File.binwrite で保存しておいて、 pf2 report コマンドに通すと、profiler.firefox.com で開けるファイルが得られます。コールスタックや flame graphなどのビジュアライズを切り替えられて便利です。
$ bundle exec pf2 report -o firefoxprofiler.json tmp/profile.pf2prof
Flame Graphビュー
しかしこの手順はいささか面倒ですので、単発のスクリプトであれば pf2 serve -- ruby target.rb のように起動することで、一気通貫でやれる方法も用意しています。この場合、計測対象のRubyコードを変更する必要はありません。
$ pf2 serve -- ruby target.rb
[Pf2] Listening on localhost:51502.
[Pf2] Open https://profiler.firefox.com/from-url/http%3A%2F%2Flocalhost%3A51502%2Fprofile for visualization.
I'm the target program!
Pf2.start, Pf2.stop を個別に呼び出すやり方など、他の方法もいくらか用意しています。詳しくはドキュメントをご確認ください。
RubyスタックとCスタックの統合表示（マジで便利）
これは他のどのプロファイラにもない、Pf2の独自機能です。CRubyやC拡張のC関数をRubyコードのプロファイルとくっつけて見られます。
require 'mysql2'
# ...
mysql.query("select * from users where name = 'osyoyu';")
普通のRubyプロファイラは、Mysql2::Client#query に時間がかかっている、よりも詳細度の高いことがわかりません。しかしPf2はその中で呼ばれているlibmysqlclientの関数レベルまでスタックを掘れるので、実際のところ何が遅いのか？ をより詳細に分析できる、という機能です。
Pure RubyなプログラムでもCRubyの関数が表示されるので、最初は面食らうかもしれません。Firefox Profilerであれば設定でNativeを非表示にすればRubyフレームに集中できるので、わずらわしかったらそうしてください。
また、CRubyでは最適化の都合で "見えない" メソッドが結構あります。たくさん呼ばれているのに無料に見えがちなものの代表格として Hash#[] があります。Pf2のRubyビューでも残念ながら見えないのですが、 rb_hash_aref() としてCスタックには出現するので尻尾を捉えられる、という点でも大変に便利です。
Pf2は他のRubyプロファイラと比べて何が良いのか
長くなりすぎたので下に移動しました。
2年の振り返り
プロファイラの開発は多くの学びと多くの機会を与えてくれました。
当初はISUCONを攻略するためにStackprofを使っていて、どうもI/O（SQLの実行待ち時間）が妙に短く表示されているな？ と気づいたのが発端だった…… はず。ISUCONの目的を考えると、データベースの待ち時間を含めたプロファイルがほしいのに、pumaのマルチスレッド下ではそれがあまり正確でなくて困った記憶があります。isucon ブランチに当時の様子が残ってます。
ささださんにも相談したところ、CRubyに rb_profile_thread_frames() を導入してもいいんじゃない、ということになり、Ruby 3.3にこれが入りました。自分がruby/rubyに入れた初のコミットはこれなのですが、最初のPRがAPIの追加なのは今思うとちょっとすごいですね。
2024年度Rubyアソシエーション開発助成金に採択され、k0kubunさんをメンターにつけてもらい、金銭的にも支援をいただきました。この場で改めてお礼を申し上げます。RubyKaigi 2024でもその成果を発表する機会をいただき、同年にプロファイラについて発表したJohn HawthornやIvo Anjoともたくさん議論（"カンファレンス"）できました。RubyKaigi 2024は自分の中で伝説の回です。
かくしてプロファイラに関する課題意識が……ある！！！ という発表をしたわけですが、この機にRubyコミュニティの知人がたくさん増え、イベント等に参加するのもすごく楽しくなりました。
ところでごく初期はCで開発していたのですが、Cの機能不足が苦しくRustに乗り換え、しかしRustはRustでRubyとの連携が難しく、またCに戻ってきました。ただ書き換えたというわけではなく、途中でpprofやJVMから得たプロファイリング自体の知識の増分、それとCRubyの知識を反映しているので、実装の方針そのものがこなれてきているはずです。
ずっと辛いと思っていることの一つにテストがあります。テストマシンごとに性能が異なるからふんわりしたアサーションしか書けないのもそうですが、そもそもRubyプログラムの性能特性自体が非決定的なことが悩みです。あるメソッドが30%の時間を消費していた、というプロファイルがあるとき、その正しさを評価するための「真の値」はどうすれば得られるのでしょう？ Stackprofと比べてPf2の結果の方が正しいと、どう証明すればいいのでしょう？
手元には穴が開くほどプロファイルを見つめたRubyスクリプトがいくつかあり、そのプロファイル結果を比較することで検証としていますが、確信めいたものはないです。ここに知見がある方はぜひ良いやり方を教えてほしいです。
やれてないことを一つ挙げるとするならば、Pf2を使ってもらえるように働きかけることであったように思います。遅いRubyプログラムを簡単に速くできるんだから、なんか遅いなぁと思っている人に使ってもらいやすいようにするべきでしたね。（実は仕事でも理想的な形では導入できておらず、まだまだやれる余地がありました）この記事をようやく書いているのもその一環ということにします。
今後
より良いプロファイリングのアイデアはいくつもあります。公私の時間の使い方をうまく調節して、実装を進めていきたい所存です。
コードを書かなければいけない課題として、プロファイリング自体の機能向上（Ractor（M:N）対応、fork対応、Flame Scope対応）と、使い勝手の向上（APIの洗練、Railsへのインテグレーション）がありそうです。CRubyのbuiltin profilerも検討したいところです。Pf2については大規模なアプリケーションへの導入もやってみて、事例を共有したいなと思っています。
RubyKaigi 2026の時期までにはv1.0.0を公開するつもりです。すばらしいバージョンになるはずなので、ご期待ください！
Pf2は他のRubyプロファイラと比べて何が良いのか
Ruby (CRuby) にはruby-prof、Stackprof、Vernier、rbspy、Datadog Continuous Profiler（実装はdd-trace-rb）など、いくらかの選択肢があります。先述したCスタックのプロファイルはPf2にオンリーワンな機能（なのでぜひ使ってほしい）ですが、他の観点でも比べてみます。
簡単に結論：いま時点でRailsをプロファイルしたいならばPf2かVernierを使うべきです。有料なものも候補ならばDatadogもすばらしいです。Stackprofは有名ですが、他のプロファイラのほうが可視化や正確性に明らかに優れるので、使う理由はもうあまりないです。
- ruby-profと比較して
- この記事中で名前が挙がる他のすべてのプロファイラと異なり、ruby-profはトレーシングプロファイラです。すべてのメソッドの呼び出しにフックし、かかった時間を記録します。メソッドの呼び出し回数は正しく記録できますが、記録自体のオーバーヘッドが大きく、計測対象の性能特性が歪みやすい方式でもあります。
- 対して、Pf2はサンプリングプロファイラです。一定周期（デフォルトでは10 ms）ごとにプログラムに介入し、その瞬間に何をしていたかを記録します。1秒間に高々100回以上の記録は起こらないため、オーバーヘッドも低く抑えられます。
- 一度だけ呼ばれ、わずかな時間だけ実行される処理は記録できないという欠点もあります。一般に、そのような処理は性能上の問題を引き起こすことは少なくはあります。
- Stackprofと比較して
- Rubyのプロファイル界を長く牽引してきたプロファイラです。名前がかっこいいですよね。
- しかし複数のスレッドがあるとき、Stackprofで得られる結果はあまり正確ではない、という欠点があります。これはStackprofのスタックの取得タイミングによるものです。
- 計測タイミングをシグナルで受け取ったあと、スタックのウォークを "安全な" タイミングまでPostponed Job APIで遅延させているからです。
- 普通のシグナルプログラミングでは良い行いではあるものの、プロファイラの世界では "Safepoint Bias" と呼ばれる現象を引き起こすことが知られています。
- Pf2にはこの問題はありません。
- ビジュアライズでも、複数のスレッドを分離して表示できません（そのために必要な情報を記録していません）。
- Vernierと比較して
- Vernierも新進気鋭のRubyプロファイラです。Pf2とだいたい同時期に開発を始めていたようです（当時は全然気づいていなかったです）。
- Rack Middlewareを提供してくれていたり、自分のコード / Gemのコードを区別して表示してくれたり、Firefox Profiler上でコードとサイドバイサイドで結果を確認できるなど、Vernierのほうが便利に使えると思います。
- Vernierはwall timeの計測に特化している一方、Pf2はwall timeとCPU timeの両方を計測できます。つまりPf2ではI/Oの時間（SQLの実行待ち）などの影響を排除して計測できる、ということです。
- どちらが良いというものではなく、wall time/cpu timeそれぞれに必要なシーンはありますが、選択肢があるのはいいことだと考えています。
- これはVernierはサンプリングのタイミングを図るためにタイマースレッドを起動する一方、Pf2はカーネルタイマーを使うためです。CPU timeはユーザーランドからは正確に計測できません。
- これを書いていて気づいたんですが、wall timeの計測精度はPf2 v0.10.0以降悪くなっているかもしれません。確かめます。
- rbspyと比較して
- rbspyは他と一風変わった方式です。CRubyのプロセスの中からプロファイルするのではなく、
process_vm_readv(2)を使って外部からメモリのスナップショットを取り、それを解釈する方式です。 - rbspyの起動には特権（root）が必要です。ECSのようなで使うにはちょっとめんどうかもしれません。
- rbspyはこの方式のプロファイラのフロンティア（開拓者）ということもあり、強い尊敬の念があります。
- rbspyは他と一風変わった方式です。CRubyのプロセスの中からプロファイルするのではなく、
- Datadog Continuous Profiler (dd-trace-rb) と比較して
- 私はこのプロファイラの大ファンです。
- すごくよくできています。DatadogのWebビジュアライザもとても使いやすいです。
- 結構いい利用料を払わないといけないのですが……
- 一応書いておくと、Pf2は無料です。
- 使えるなら使うといいと思います。