ローファイ日記

出てくるコード片、ぼくが書いたものは断りがない場合 MIT License としています http://udzura.mit-license.org/

RubyKaigi 後日譚: GC のレイテンシを可視化する人の補足

本日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の対象が増えるわけではないためかそちらへの影響はそこまで大きくありません。

動画も作っています。以下です。

www.youtube.com

RSSの計算にはprocfsの情報を、そしてMark/Sweepの回数とレイテンシの計測にUSDTと、BPF、RbBCCを使いました。

そしてこのツール自体は USDT有効ビルドのRubyを使っていればどんなアプリケーションにも使える ので、現場のpumaやfluentdのGCレイテンシの計測にそのまま使えるかもしれません。USDT有効ビルドのRubyを準備するのがそれなりにハードルですが挑戦してみてください。

コードの全体は こちら です。

Observability用途のBPFを活用する際、例えばファイルアクセスやネットワークのレイテンシなどを計測するにしても、前提としてカーネル内部の知識が必要になりがちです。一方USDTやuprobeであれば、対象アプリケーションの中身がわかっていれば活用できます。いろいろな用途が見つかるといいなと思います。

と言いたかった。

会期はまだまだ残っていて、私も会場をうろうろとしていますので、興味のある方はお声がけください！

*1:うなすけさん、気にすることないですよ！

*2:識者に補足いただきたい...