本日RubyKaigiでお話ししてきました。BPFのObservability関連の機能を紹介しながら実際にサンプルをRuby で書いていくみたいな流れでした。以下に資料を。
docs.google.com
一番見せたかった「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が使えます)、
magazine.rubyist.net
kosakiさんによる解説などをどうぞ。
作ったもの
生きているRuby プロセスに対してアタッチし、1秒ごとに以下を表示します。
その時のRSS (Resident Set Size)
1秒間に実行されたGC Markの回数と平均実行時間
1秒間に実行されたGC Sweepの回数と平均実行時間
$ 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の対象が増えるわけではないためかそちらへの影響はそこまで大きくありません。
動画も作っています。以下です。
VIDEO www.youtube.com
RSS の計算にはprocfsの情報を、そしてMark/Sweepの回数とレイテンシの計測にUSDTと、BPF、RbBCCを使いました。
そしてこのツール自体は USDT有効ビルドのRuby を使っていればどんなアプリケーションにも使える ので、現場のpumaやfluentdのGC レイテンシの計測にそのまま使えるかもしれません。USDT有効ビルドのRuby を準備するのがそれなりにハードルですが挑戦してみてください。
コードの全体は こちら です。
Observability用途のBPFを活用する際、例えばファイルアクセスやネットワークのレイテンシなどを計測するにしても、前提としてカーネル 内部の知識が必要になりがちです。一方USDTやuprobeであれば、対象アプリケーションの中身がわかっていれば活用できます。いろいろな用途が見つかるといいなと思います。
と言いたかった。
会期はまだまだ残っていて、私も会場をうろうろとしていますので、興味のある方はお声がけください!