Rubyアプリケーションでスレッドが停止する様子を計測する（翻訳）
前回の記事↓で、IO-boundなRailsアプリケーションの本当の姿について書いたとき、CPU枯渇をIO速度低下と見間違えてしまうというよくある落とし穴について述べました。
start = Time.now
database_connection.execute("SELECT ...")
query_duration = (Time.now - start) * 1000.0
puts "Query took: #{query_duration.round(2)}ms"
上記の例では、データベースがクエリに応答するのにかかった時間についてはRailsのinstrumentation（計測）機能でわかりますが、この時間には「RubyスレッドがGVL（Global VM Lock）を再取得するのに必要な時間」「Ruby GCの実行に必要な時間」「OSのスケジューラがプロセスを再開するのに必要な時間」も含まれている場合があります。
ありがたいことに、最近のRubyではこれらの測定に役立つ新しいAPIがいくつか追加されました。
🔗 GC.total_time
データベースのクエリなどのIO処理では、メモリアロケーションが大量に発生することがあります。たとえば何十個ものカラムを持つ100行のデータベースに対してSELECTを実行すると、おそらくアロケーションが1000個以上発生することが予想され、それらのどれかが計測中のコードブロック内の実行中にGC（ガベージコレクション）をトリガーする可能性があります。
したがって、RubyがGCにどのぐらい時間を割いているかを監視しておくのはよい考えです。これをやりやすくするため、私はRubyの古いバグトラッカーを復活させて（#10917#note-4）、新しいGC.total_time APIを実装するようKoichi Sadasaを説得しました（#4757）。
このアクセサは単調増加するカウンタで、GCを費やした時間をナノ秒で表します。つまり、GC中に特定のコードブロックが費やした時間を知るには、単純に引き算すればよいのです。
def time_in_gc
before = GC.total_time
yield
diff_ms = (GC.total_time - before) / 1_000_000.0
puts "gc_time: #{diff_ms.round(2)}ms"
end
time_in_gc do
2_000_000.times { Object.new }
end
gc_time: 24.18ms
もちろん、マルチスレッドアプリケーションを実行している場合は、別のスレッドがGCに要した時間の原因になっている可能性があるため、測定されたIO時間からGCに要した時間を単純に引き算するわけにはいきませんが、それを計測してIO期間の横に表示することは、やはり良い考えです。
私がRails 7.2でこの測定項目をRailsのinstrumentation APIに追加したのは、そのためです#51770。
ActiveSupport::Notificationsのあらゆるイベントにgc_timeが含まれるようになり、RailsのリクエストログにGCに要した全体時間が含まれるようになりました。
GVL用のInstrumentation API
GCよりもさらに起きがちなのは、GVLの競合です。アプリケーションに設定したスレッド数が多すぎると、一部のIOが終了後にスレッドが再開するまでの遅延が長くなる可能性があります。
そういうわけで、Ruby 3.2.1ではGVL計測用のC APIを新たに追加しました（#18339）。
かなり低レベルのAPIなので、これを統合するにはC拡張が必要ですが、私はそれ用のgvltools を書きました。また、John Hawthornが書いたgvl_timing gemやIvo Anjoが書いたgvl-tracingもあります。
gvltoolsを用いてGCLの待ち時間から実際のIO時間を見分ける方法を以下に示します。
require "bundler/inline"
gemfile do
gem "bigdecimal" # trilogy用
gem "trilogy"
gem "gvltools"
end
GVLTools::LocalTimer.enable
def measure_time
realtime_start = Process.clock_gettime(Process::CLOCK_MONOTONIC, :float_millisecond)
gvl_time_start = GVLTools::LocalTimer.monotonic_time
yield
realtime = Process.clock_gettime(Process::CLOCK_MONOTONIC, :float_millisecond) - realtime_start
gvl_time = GVLTools::LocalTimer.monotonic_time - gvl_time_start
gvl_time_ms = gvl_time / 1_000_000.0
io_time = realtime - gvl_time_ms
puts "io: #{io_time.round(1)}ms, gvl_wait: #{gvl_time_ms.round(2)}ms"
end
trilogy = Trilogy.new
# 最初はメインスレッドのみで測定する
measure_time do
trilogy.query("SELECT 1")
end
def fibonacci( n )
return n if ( 0..1 ).include? n
( fibonacci( n - 1 ) + fibonacci( n - 2 ) )
end
# CPU負荷の大きいスレッドを5つ立ち上げる
threads = 5.times.map do
Thread.new do
loop do
fibonacci(25)
end
end
end
# 今度はバックグラウンドスレッドを測定
measure_time do
trilogy.query("SELECT 1")
end
上の例を実行すると、最初の測定ではGVLの待ち時間がほぼゼロになっていますが、2回目では0.5秒もの大きなオーバーヘッドが追加されていることがわかります。
realtime: 0.22ms, gvl_wait: 0.0ms, io: 0.2ms
realtime: 549.29ms, gvl_wait: 549.22ms, io: 0.1ms
ただしこのAPIは、Rubyのスレッドスケジューラに少々オーバーヘッドをもたらすという欠点があります。このオーバーヘッドがどのくらいなのかを厳密に導き出すことまではできませんでしたが、おそらく無視して構わない程度だと思いますが、それまでは、このAPIをRailsのデフォルトとして統合することは正当化しにくいでしょう。
とは言うものの、SpeedshopのYuki Nishijimaがgvl_metrics_middlewareというオープンソースのミドルウエアを公開していて、これを使うと新しいinstrumenttion APIをさまざまなAPM（アプリケーションパフォーマンス管理）サービスにフックできるので、今後さらに用途が広がることが見込まれそうです。
🔗 OSのスケジューラ
IO操作が実際より時間がかかっているように見える原因の残る1つは、OSのスケジューラです。
アプリケーションを専用ハードウェアで実行して、コアごとに1つのRubyプロセスだけを生成するようにしない限り、OSが一部のIOブロックを終了した後、プロセスをすぐに再開しないことがあります。
残念ながら、これを測定する真に正しい方法は私にはわかりません。
探した中で最もましだったのは、Linux上の/proc/<pid>/schedstatでした。
# cat /proc/1/schedstat
40933713 1717706 178
リストの2番目の数字は、特定のプロセスが「runqueue」で費やした時間（ナノ秒）、つまり、作業を再開するためにCPUコアが割り当てられるまで待機した時間です。
しかし、/procのIOをすべて読み取るのは少々面倒なので、アプリケーション監視にはこれまで統合していません。代わりに、コンテナー内で実行されているプロセスが多すぎることを示す指標として、マシンごとにグローバルに監視します。
🔗 まとめ
そういうわけで、特定のIO操作に要した時間を正確に測定するのは非常に困難なのですが、アプリケーションで「スレッドの停止」がどの程度発生しているかをより正確に把握するのに役立つ一般的なメトリクスはいくつかあります。
私はさまざまなアプリケーションパフォーマンス監視サービスに目を光らせているわけではありませんが、上述の新しいAPIを追加したとき、最終的にこうしたサービスに統合されることを期待していました。既に統合されているものがあるかどうかはわかりません。
概要
元サイトの許諾を得て翻訳・公開いたします。
参考: Active Support Instrumentation で計測 - Railsガイド