Ruby: メソッドを最速でプロファイリングする方法(翻訳)

概要

原著者の許諾を得て翻訳・公開いたします。

Ruby: メソッドを最速でプロファイリングする方法(翻訳)

Rubyのメソッドを最短かつ洗練された方法でプロファイリングできる方法はどれでしょうか?

最近私たちのDiscourseにいくつかのinstrumentationを追加する必要が生じました。あらゆるリクエストを測定対象に加えたかったのです。

  • SQL文やRedisコマンドの実行数
  • 特定のセクションの実行に要する時間

これは、より一般性の高い問題に簡単に抽象化できます。

class ExternalClass
   def method_to_measure
   end
end

この問題を解決するうえで、いくつかのサブ問題に分割します。

  1. あるメソッドの実行にかかった時間を最短で測定できる方法は何か

  2. あるメソッドにinstrumentationを最も手軽に追加できるパッチは何か

  3. マルチスレッドにどう配慮するか

1. 最短のメソッド測定方法

最初に解決すべき最もシンプルな問題は、パッチが当たっていないかのように見せかけることです。

ありとあらゆるソースコードを開いて望みのinstrumentationを片っ端から追加してよいと仮定した場合、経過時間を最短で測定できるのはどんな方法でしょうか?

Rubyで使える手法は次の2とおりが考えられます。

  1. ある瞬間の直前と直後にわたってTimeオブジェクトを作成する
  2. ある瞬間の直前と直後にわたってProcess.clock_gettimeFloatを返す

それでは測定してみましょう。

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を使ってインストラクションシーケンスを強引に出力し、そこにパッチを当ててからメソッドを読み込むというものです。パッチを最速で当てられる方法であることは間違いありませんが、インストラクションシーケンスの改変という裏技は少々闇が深すぎるので常に使えるとは限りません。

それではprependalias_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つが考えられます。

  1. Thread.currentがプロファイル対象のスレッドである場合に限ってinstrumentationを実行する
  2. 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のクラスをかなり効率よく設計できるようになります。

本記事のどのコードも、帰属の表示の有無にかかわらずご自由に利用・構築いただけます。

関連記事

RailsのパフォーマンスをPrometheusで測定する(翻訳)

デザインも頼めるシステム開発会社をお探しならBPS株式会社までどうぞ 開発エンジニア積極採用中です! Ruby on Rails の開発なら実績豊富なBPS

この記事の著者

hachi8833

Twitter: @hachi8833、GitHub: @hachi8833 コボラー、ITコンサル、ローカライズ業界、Rails開発を経てTechRachoの編集・記事作成を担当。 これまでにRuby on Rails チュートリアル第2版の半分ほど、Railsガイドの初期翻訳ではほぼすべてを翻訳。その後も折に触れてそれぞれ一部を翻訳。 かと思うと、正規表現の粋を尽くした日本語エラーチェックサービス enno.jpを運営。 実は最近Go言語が好き。 仕事に関係ないすっとこブログ「あけてくれ」は2000年頃から多少の中断をはさんで継続、現在はnote.muに移転。

hachi8833の書いた記事

週刊Railsウォッチ

インフラ

ActiveSupport探訪シリーズ