概要
原著者の許諾を得て翻訳・公開いたします。
- 英語記事: Fastest way to profile a method in Ruby
- 原文公開日: 2017/10/08
- 著者: Sam Saffron -- Discourseの共同創業者であり、Stack Overflowでの開発経験もあります。
Ruby: メソッドを最速でプロファイリングする方法（翻訳）
Rubyのメソッドを最短かつ洗練された方法でプロファイリングできる方法はどれでしょうか？
最近私たちのDiscourseにいくつかのinstrumentationを追加する必要が生じました。あらゆるリクエストを測定対象に加えたかったのです。
- SQL文やRedisコマンドの実行数
- 特定のセクションの実行に要する時間
これは、より一般性の高い問題に簡単に抽象化できます。
class ExternalClass
def method_to_measure
end
end
この問題を解決するうえで、いくつかのサブ問題に分割します。
- あるメソッドの実行にかかった時間を最短で測定できる方法は何か
-
あるメソッドにinstrumentationを最も手軽に追加できるパッチは何か
-
マルチスレッドにどう配慮するか
1. 最短のメソッド測定方法
最初に解決すべき最もシンプルな問題は、パッチが当たっていないかのように見せかけることです。
ありとあらゆるソースコードを開いて望みのinstrumentationを片っ端から追加してよいと仮定した場合、経過時間を最短で測定できるのはどんな方法でしょうか？
Rubyで使える手法は次の2とおりが考えられます。
- ある瞬間の直前と直後にわたって
Timeオブジェクトを作成する - ある瞬間の直前と直後にわたって
Process.clock_gettimeでFloatを返す
それでは測定してみましょう。
require 'benchmark/ips'
class Test
attr_reader :count, :duration
def initialize
@count = 0
@duration = 0.0
end
def work
end
def method
work
end
def time_method
@count += 1
t = Time.now
work
ensure
@duration += Time.now - t
end
def process_clock_get_time_method
@count += 1
t = Process.clock_gettime(Process::CLOCK_MONOTONIC)
work
ensure
@duration += Process.clock_gettime(Process::CLOCK_MONOTONIC) - t
end
end
t = Test.new
Benchmark.ips do |b|
b.report "method" do |times|
i = 0
while i < times
t.method
i += 1
end
end
b.report "time_method" do |times|
i = 0
while i < times
t.time_method
i += 1
end
end
b.report "process_clock_get_time_method" do |times|
i = 0
while i < times
t.process_clock_get_time_method
i += 1
end
end
end
# Calculating -------------------------------------
# method 19.623M (± 3.5%) i/s - 98.227M in 5.012204s
# time_method 1.596M (± 1.2%) i/s - 8.061M in 5.050321s
# process_clock_get_time_method
# 4.972M (± 1.7%) i/s - 24.908M in 5.011634s
Process.clock_gettime(Process::CLOCK_MONOTONIC)ではオブジェクトの割り当ても後からのガベージコレクションも発生しないので、予想どおり最速です。ついでながら、これは最も正確に期間を測定できる方法です。
ではさしあたってこれを使うことにしましょう。
#workが空である件について
上述の方法では#workになっていますが、ここで何らかの処理を行うと、2つの方法の違いはかなり微妙になります。
たとえば、workを$redis.get('x')（これはできるだけ最短時間で測定したいと思っている項目です）に置き換えたとすると、次の結果が得られます。
method 17.567k (± 3.0%) i/s - 88.230k in 5.027068s
time_method 16.730k (± 3.2%) i/s - 84.864k in 5.077868s
process_clock_get_time_method
17.112k (± 2.7%) i/s - 85.884k in 5.022470s
つまりredisを1秒間にそれぞれ17500回/17110回/16700回実行できることになり、測定なしの場合が最速、最も低速なのはTime.nowになります。
最初のベンチマークに比べれば大した差ではありませんが、もっと高速かつ安全な方法が他にあるなら、Time.nowという高い税金を払おうという人などいないでしょう。
2. メソッドに最短でパッチを当てる方法
測定するコードが私たちが所有していないものである場合、ソースレベルの変更などという贅沢はできません。
残る手段は次の3つです。
- 対象となるクラスにモジュールを
prependして元のメソッドをオーバーライドする alias_methodを使って元のメソッドのあたりに新しいメソッドをチェインする- 対象のメソッドを「パッチ適用版メソッド」に置き換える
メソッドの置き換えは危険がいっぱいです。サードパーティライブラリ内のメソッドが変更されてしまえばパッチの修正が必要ですし、長期間のメンテも無理な相談です。もうひとつ興味深いオプションについて後述しますが、これはRubyVM::InstructionSequence#ofを使ってインストラクションシーケンスを強引に出力し、そこにパッチを当ててからメソッドを読み込むというものです。パッチを最速で当てられる方法であることは間違いありませんが、インストラクションシーケンスの改変という裏技は少々闇が深すぎるので常に使えるとは限りません。
それではprependとalias_methodを比較した場合どちらが速いのでしょうか？
require 'benchmark/ips'
#require 'redis'
#$redis = Redis.new
class Test
attr_reader :count
def initialize
@count = 0
end
def work
# $redis.get 'X'
end
def method
work
end
def method_with_prepend
work
end
def method_with_alias_method
work
end
def method_with_manual_instrument
@count += 1
work
end
end
module PrependInstrument
def method_with_prepend
@count += 1
super
end
end
class Test; prepend PrependInstrument; end
class Test
alias_method :method_with_alias_method_orig, :method_with_alias_method
def method_with_alias_method
@count += 1
method_with_alias_method_orig
end
end
t = Test.new
Benchmark.ips do |b|
b.report "method" do |times|
i = 0
while i < times
t.method
i += 1
end
end
b.report "method_with_prepend" do |times|
i = 0
while i < times
t.method_with_prepend
i += 1
end
end
b.report "method_with_alias_method" do |times|
i = 0
while i < times
t.method_with_alias_method
i += 1
end
end
b.report "method_with_manual_instrument" do |times|
i = 0
while i < times
t.method_with_manual_instrument
i += 1
end
end
end
# method 20.403M (± 1.6%) i/s - 102.084M in 5.004684s
# method_with_prepend 10.339M (± 1.5%) i/s - 51.777M in 5.009321s
# method_with_alias_method
# 13.067M (± 1.8%) i/s - 65.649M in 5.025786s
# method_with_manual_instrument
# 16.581M (± 1.6%) i/s - 83.145M in 5.015797s
prepend法はメソッドへのパッチとしては極めて洗練されていますが、古臭いalias_method法に速度でかなり負けています。
しかし#workに処理を導入するとその差はかなり微妙になります。同じベンチマークを#workで$redis.get "x"を実行した場合の結果は以下のとおりです。
method 17.259k (± 3.1%) i/s - 86.892k in 5.039493s
method_with_prepend 17.056k (± 2.8%) i/s - 85.782k in 5.033548s
method_with_alias_method
17.464k (± 2.4%) i/s - 87.464k in 5.011238s
method_with_manual_instrument
17.369k (± 2.8%) i/s - 87.204k in 5.024699s
パフォーマンスはほぼ拮抗しているので、下手をすると違いに気づかないかもしれません。
3. スレッドへの配慮
今回のユースケースで最も頭を痛めたのは、測定結果が現在のスレッドだけに基づいていることをどのように保証するかでした。
Discourseではいくつかのバックグラウンドスレッドが遅延処理を実行していることがあり、Webサービスを提供しているそうしたスレッドが測定結果に干渉しないようにしたかったのです。Pumaベースの環境では、同一のグローバルスレッドセーフRedis接続に多数のスレッドがアクセスするため、臨界点を超えてしまいます。接続をオープンする前にinstrumentationを有効にしておく手もあります。
それではスレッドセーフの影響を測定することにしましょう。
require 'benchmark/ips'
require 'redis'
$redis = Redis.new
class Test
attr_reader :count
def initialize
@count = 0
@thread = Thread.current
data = Struct.new(:count).new
data.count = 0
Thread.current["prof"] = data
end
def work
# $redis.get 'X'
end
def method
work
end
def method_with_safety
@count += 1 if Thread.current == @thread
work
end
def method_with_thread_storage
if data = Thread.current["count"]
data.count += 1
end
work
end
end
t = Test.new
Benchmark.ips do |b|
b.report "method" do |times|
i = 0
while i < times
t.method
i += 1
end
end
b.report "method_with_safety" do |times|
i = 0
while i < times
t.method_with_safety
i += 1
end
end
b.report "method_with_thread_storage" do |times|
i = 0
while i < times
t.method_with_thread_storage
i += 1
end
end
end
スレッド安全性に配慮する手法として次の2つが考えられます。
Thread.currentがプロファイル対象のスレッドである場合に限ってinstrumentationを実行する- instrumentationデータを
Thread.currentに保存する（外部レジストリは速度が落ちる点に注意）
Thread.currentの比較を使う方法が高速であることは見当が付きますが、処理を始めてみるとこの違いはほとんどありません。安全性のためのコストはかかるものの、大きなコストではありません。
### `work`が空の場合
method 20.119M (± 3.1%) i/s - 100.579M in 5.004172s
method_with_safety 11.254M (± 3.0%) i/s - 56.509M in 5.025966s
method_with_thread_storage
6.105M (± 3.5%) i/s - 30.559M in 5.011887s
workが$redis.get 'x'の場合は以下のようになります。
method 18.007k (± 4.8%) i/s - 91.052k in 5.069131s
method_with_safety 18.081k (± 2.9%) i/s - 91.156k in 5.045869s
method_with_thread_storage
18.042k (± 2.8%) i/s - 90.532k in 5.021889s
4. 一般的なメソッドプロファイラ
ここまで登場した要素をひとつにまとめ、最速のマイクロベンチを用いて一般的なメソッドプロファイラを組み立て、測定値を収集します。
# instrumentationでパッチを適用するために1度呼び出される
MethodProfiler.patch(SomeClass, [:method1, :method2], :name)
SomeClass.new.method1
SomeClass.new.method2
# プロファイリング開始時に呼び出される
MethodProfiler.start
result = MethodProfiler.stop
{
total_duration: 0.2,
name: {duration: 0.111, calls: 12}
}
これで以下のように実装できます（Gist）。
require 'benchmark/ips'
require 'redis'
class MethodProfiler
def self.patch(klass, methods, name)
patches = methods.map do |method_name|
<<~RUBY
unless defined?(#{method_name}__mp_unpatched)
alias_method :#{method_name}__mp_unpatched, :#{method_name}
def #{method_name}(*args, &blk)
unless prof = Thread.current[:_method_profiler]
return #{method_name}__mp_unpatched(*args, &blk)
end
begin
start = Process.clock_gettime(Process::CLOCK_MONOTONIC)
#{method_name}__mp_unpatched(*args, &blk)
ensure
data = (prof[:#{name}] ||= {duration: 0.0, calls: 0})
data[:duration] += Process.clock_gettime(Process::CLOCK_MONOTONIC) - start
data[:calls] += 1
end
end
end
RUBY
end.join("\n")
klass.class_eval patches
end
def self.start
Thread.current[:_method_profiler] = {
__start: Process.clock_gettime(Process::CLOCK_MONOTONIC)
}
end
def self.stop
finish = Process.clock_gettime(Process::CLOCK_MONOTONIC)
if data = Thread.current[:_method_profiler]
Thread.current[:_method_profiler] = nil
start = data.delete(:__start)
data[:total_duration] = finish - start
data
end
end
end
$redis = Redis.new
class Test
def work
#$redis.get 'X'
end
def method
work
end
def method_unpatched
work
end
end
MethodProfiler.patch(Test, [:method], :a_thing)
MethodProfiler.start
t = Test.new
Benchmark.ips do |b|
b.report "method" do |times|
i = 0
while i < times
t.method
i += 1
end
end
b.report "method_unpatched" do |times|
i = 0
while i < times
t.method_unpatched
i += 1
end
end
end
「workが空」のシナリオでは、予想どおりパフォーマンスに明確な違いが生じます。
（プロファイリング中）
method 2.247M (± 1.6%) i/s - 11.370M in 5.061768s
method_unpatched 20.261M (± 3.5%) i/s - 101.226M in 5.002638s
（プロファイリングなし）
method 6.015M (± 2.9%) i/s - 30.156M in 5.017655s
method_unpatched 20.211M (± 2.1%) i/s - 101.288M in 5.013976s
そして実際にworkに`$redis.get 'x'を入れると、次の結果になります。
（プロファイリング中）
method 17.419k (± 3.5%) i/s - 87.108k in 5.006821s
method_unpatched 17.627k (± 7.3%) i/s - 88.740k in 5.063757s
（プロファイリングなし）
method 17.293k (± 3.1%) i/s - 87.672k in 5.074642s
method_unpatched 17.478k (± 2.4%) i/s - 88.556k in 5.069598s
5. 結論
あらゆるマイクロベンチマークを基礎とすることで、実行時の影響を最小限に留めたメソッドプロファイリング用の一般的なRubyのクラスをかなり効率よく設計できるようになります。
本記事のどのコードも、帰属の表示の有無にかかわらずご自由に利用・構築いただけます。