本日RubyKaigiでお話ししてきました。BPFのObservability関連の機能を紹介しながら実際にサンプルをRubyで書いていくみたいな流れでした。以下に資料を。
一番見せたかった「RubyのGC関係USDTを用いてレイテンシを可視化する」というツールのデモが...流せなかったので*1、心残りを洗い流すべく補足記事を書きます。
USDT？
Rubyを特定のオプション --enable-dtrace でconfigureしてビルドすると、USDTと呼ばれる情報がRubyのバイナリに付与されます。この情報を使うとRubyの生きているプログラムに対して、さまざまな細かい情報を取得できるようになります。例えば以下のタイミングでイベントがフックされます。
- オブジェクト一般、シンボル、文字列、配列、ハッシュの作成
- C定義のメソッドの呼び出し、リターン
- GCの開始、終了
- 例外発生
そもそもTracePointという機構もありますが、TracePointがプログラムパフォーマンスに大きく影響を与えることは周知のことです。USDT経由で、かつBPFのような仕組みで情報を取得すると実用上影響ないレベルの副作用で細かい情報が取得できます。はず。
ところでUSDTを調べていると「dtrace」という言葉がよく出てきますが、USDTという概念はそもそもDTraceの文脈で出てきたもののようで、それをLinuxでも使えるようにした感じで進化してきたもの*2みたいです。
詳細は、aaronによるるびまのDTrace紹介（first introduced in 2.0なんですよね / 全く同じProbeが使えます）、
kosakiさんによる解説などをどうぞ。
作ったもの
生きているRubyプロセスに対してアタッチし、1秒ごとに以下を表示します。
$ sudo ruby ./gcsnoop.rb 186197 $(rbenv which ruby) Start tracing TIME EVENT RSS(KB) ELAPSED(ms/event) 2022-09-09 15:22:52.487468 RSS 23372 2022-09-09 15:22:53.500447 MARK - 2022-09-09 15:22:53.505751 SWEEP - 2022-09-09 15:22:53.531737 RSS 23204 2022-09-09 15:22:54.603751 MARK - 2022-09-09 15:22:54.604788 SWEEP - 2022-09-09 15:22:54.637420 RSS 23444 2022-09-09 15:22:55.712456 MARK - 2022-09-09 15:22:55.712677 SWEEP 0.250, 1 time(s) 2022-09-09 15:22:55.740717 RSS 23588 2022-09-09 15:22:56.799344 MARK - 2022-09-09 15:22:56.801217 SWEEP - 2022-09-09 15:22:56.834391 RSS 23672 2022-09-09 15:22:57.908051 MARK - 2022-09-09 15:22:57.908299 SWEEP 0.149, 1 time(s) 2022-09-09 15:22:57.941105 RSS 23756
実験としてわざとメモリリークするようなSinatraのアプリを書きました。これはひどいですが、実験です。
require 'sinatra' $count = 0 $leak = [] $next = 100 puts "LEAK MODE: #{! ENV["LEAKY"].nil?}" get '/' do if ENV["LEAKY"] $leak << (1..100).map { Object.new } end "OK" end
$ LEAKY=1 ruby sinatra-app.rb 2>/dev/null &
LEAK MODE: true
Puma starting in single mode...
* Puma version: 5.6.5 (ruby 3.1.2-p20) ("Birdie's Version")
* Min threads: 0
* Max threads: 5
* Environment: development
* PID: 187396
* Listening on http://127.0.0.1:4567
* Listening on http://[::1]:4567
Use Ctrl-C to stop
$ ps auxf | grep -e RSS -e puma
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
ubuntu 187441 1.0 0.3 363388 26396 pts/3 Sl 15:26 0:00 | \_ puma 5.6.5 (tcp://localhost:4567) [rk2022-benchtools]
$ ab -c 1000 -t 10 http://127.0.0.1:4567/
...
$ ps auxf | grep -e RSS -e puma
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
ubuntu 187515 33.5 3.6 855116 295512 pts/3 Sl 15:27 0:21 | \_ puma 5.6.5 (tcp://localhost:4567) [rk2022-benchtools]
簡単にRSSを肥大化させることができます。GCがどうなるか見てみます。
$ sudo ruby ./gcsnoop.rb 187441 $(rbenv which ruby) Start tracing TIME EVENT RSS(KB) ELAPSED(ms/event) 2022-09-09 15:30:01.415746 RSS 22860 2022-09-09 15:30:02.489423 MARK - 2022-09-09 15:30:02.489839 SWEEP - 2022-09-09 15:30:02.526016 RSS 22860 ... 2022-09-09 15:30:28.291423 RSS 22860 2022-09-09 15:30:29.292707 MARK 0.552, 17 time(s) 2022-09-09 15:30:29.292734 SWEEP 0.055, 254 time(s) 2022-09-09 15:30:29.297429 RSS 49260 2022-09-09 15:30:30.298606 MARK 1.274, 6 time(s) 2022-09-09 15:30:30.298636 SWEEP 0.060, 247 time(s) 2022-09-09 15:30:30.304768 RSS 63364 2022-09-09 15:30:31.306836 MARK 1.408, 4 time(s) 2022-09-09 15:30:31.306866 SWEEP 0.059, 255 time(s) 2022-09-09 15:30:31.311147 RSS 83784 2022-09-09 15:30:32.312385 MARK 2.297, 2 time(s) 2022-09-09 15:30:32.312416 SWEEP 0.061, 230 time(s) 2022-09-09 15:30:32.317398 RSS 111252 2022-09-09 15:30:33.318531 MARK 4.285, 2 time(s) 2022-09-09 15:30:33.318559 SWEEP 0.067, 195 time(s) ... 2022-09-09 15:30:47.433592 RSS 389912 2022-09-09 15:30:48.434317 MARK 14.691, 1 time(s) 2022-09-09 15:30:48.434350 SWEEP 0.093, 187 time(s) 2022-09-09 15:30:48.441605 RSS 423512 2022-09-09 15:30:49.442609 MARK 2.361, 1 time(s) 2022-09-09 15:30:49.442659 SWEEP 0.072, 306 time(s) 2022-09-09 15:30:49.450451 RSS 425004 2022-09-09 15:30:50.451657 MARK - 2022-09-09 15:30:50.451685 SWEEP 0.078, 336 time(s) 2022-09-09 15:30:50.459964 RSS 432168 2022-09-09 15:30:51.461260 MARK 14.032, 1 time(s) 2022-09-09 15:30:51.461293 SWEEP 0.084, 256 time(s) 2022-09-09 15:30:51.468487 RSS 449268 2022-09-09 15:30:52.469774 MARK - 2022-09-09 15:30:52.469803 SWEEP 0.057, 171 time(s) 2022-09-09 15:30:52.477342 RSS 473020 2022-09-09 15:30:53.478389 MARK 15.491, 1 time(s) 2022-09-09 15:30:53.478409 SWEEP 0.077, 391 time(s) 2022-09-09 15:30:53.485416 RSS 480392 2022-09-09 15:30:54.486348 MARK 16.764, 1 time(s) 2022-09-09 15:30:54.486378 SWEEP 0.078, 160 time(s) 2022-09-09 15:30:54.494123 RSS 512272 2022-09-09 15:30:55.495602 MARK - 2022-09-09 15:30:55.495634 SWEEP 0.066, 414 time(s) 2022-09-09 15:30:55.503252 RSS 513088 2022-09-09 15:30:56.504433 MARK 18.446, 1 time(s) 2022-09-09 15:30:56.504460 SWEEP 0.096, 149 time(s) ... ... 2022-09-09 15:31:46.065511 RSS 1165324 2022-09-09 15:31:47.066567 MARK 34.956, 1 time(s) 2022-09-09 15:31:47.066786 SWEEP 0.104, 135 time(s)
RSSが大きくなる（＝Mark対象のオブジェクトが増える）とMarkフェーズの所要時間が増えていっていることが観測できます。RSSが1GBに達したら30ms超えになっているようです。なお、Sweepの対象が増えるわけではないためかそちらへの影響はそこまで大きくありません。
動画も作っています。以下です。
RSSの計算にはprocfsの情報を、そしてMark/Sweepの回数とレイテンシの計測にUSDTと、BPF、RbBCCを使いました。
そしてこのツール自体は USDT有効ビルドのRubyを使っていればどんなアプリケーションにも使える ので、現場のpumaやfluentdのGCレイテンシの計測にそのまま使えるかもしれません。USDT有効ビルドのRubyを準備するのがそれなりにハードルですが挑戦してみてください。
コードの全体は こちら です。
Observability用途のBPFを活用する際、例えばファイルアクセスやネットワークのレイテンシなどを計測するにしても、前提としてカーネル内部の知識が必要になりがちです。一方USDTやuprobeであれば、対象アプリケーションの中身がわかっていれば活用できます。いろいろな用途が見つかるといいなと思います。
と言いたかった。
会期はまだまだ残っていて、私も会場をうろうろとしていますので、興味のある方はお声がけください！
