背景

巨大化老朽化してきたRailsサービスのパフォーマンス改善作業を行う際、手軽に各種メソッドのベンチマークを取りながらトライアンドエラーを進めたかった。

最初は愚直にbenchmarkライブラリを使ってメソッドのベンチマークを測ろうとした。（ちなみにプロファイラはstackprofなどを使用）

sample_controller.rb

class OldCarsController < ApplicationController
  def index
    Benchmark.bm 10 do |r| # なんか無茶なやり方
      r.report "index action" do
        @q = OldCar.ransack(params[:q])
        time_consuming_method1
        time_consuming_method2
        @old_cars = @q.result(distinct: true)
      end
    end
  end
  private
  def time_consuming_method1
    sleep(1)
  end
  def time_consuming_method2
    100000.times { OldCar.new }
  end
end

例えばこんな形でindexアクションを実行すると、以下のようなログが出てindexアクションのベンチマークが取れるが、複数のメソッドやアクションのベンチマークを取ろうと思うとその度記述を追記しなくては行けないのが面倒臭いし、ログも一応ログファイルに置いておきたい。

sample.log

                  user     system      total        real
index action  2.757912   0.000000   2.757912 (  3.773948)

また、計測したい処理内容をBenchmark.bm do ~ endで囲うと、その処理部分の戻り値はベンチマークオブジェクトになるので、戻り値を他のメソッドで使用するようなメソッドだとこの計測方法は使いづらい。

sample_controller.rb

class OldCarsController < ApplicationController
  def index
    Benchmark.bm 10 do |r|
      r.report "index action" do
        @q = OldCar.ransack(params[:q])
        time_consuming_method1
        time_consuming_method2
        @old_cars = @q.result(distinct: true)
      end
    end
    # 戻り値が@old_carsの値ではなく計測結果のオブジェクトになる
    # => [#<Benchmark::Tms:0x000055d3ab7be4c0 @label="index action", @real=3.773947899997438, @cstime=0.0, @cutime=0.0, @stime=0.0, @utime=2.7579119999999993, @total=2.7579119999999993>]
  end
  # （省略）
end

と言うわけで勉強がてらこれらの問題を解消できそうなgemを作ってみた。
https://github.com/shibatadaiki/Rbenchmarker

実演

config/environments/development.rb

require "active_support/core_ext/integer/time"
Rails.application.configure do
  config.eager_load = true # 設定をtrueに変更
  config.after_initialize do # 設定を追加
    Rbenchmarker.setup switch: 'on', output_log_path: nil, except_classes: [], except_modules: []
  end
  # （省略）
end

sample_controller.rb

class OldCarsController < ApplicationController
  rbenchmarker all: __FILE__ # 記述を追加
  def index
  # （省略）
end

こんな感じで準備して、indexアクションを叩くと

log/rbenchmark.log

# Logfile created on 2021-02-11 17:18:16 +0000 by logger.rb/v1.4.2
I, [2021-02-11T17:18:16.305563 #1]  INFO -- : == Start recording Rbenchmarker == 
I, [2021-02-11T17:18:43.097913 #1]  INFO -- : 
report def time_consuming_method1 instance method: current time
user: 0.00265500, system: 0.00019400, total: 0.00284900, real: 1.00423010
report def time_consuming_method1 instance method: total time for 1 times called
user: 0.00265500, system: 0.00019400, total: 0.00284900, real: 1.00423010
report def time_consuming_method1 instance method: avarage time
user: 0.00265500, system: 0.00019400, total: 0.00284900, real: 1.00423010
I, [2021-02-11T17:18:45.519836 #1]  INFO -- : 
report def time_consuming_method2 instance method: current time
user: 2.40189500, system: 0.00000000, total: 2.40189500, real: 2.41995030
report def time_consuming_method2 instance method: total time for 1 times called
user: 2.40189500, system: 0.00000000, total: 2.40189500, real: 2.41995030
report def time_consuming_method2 instance method: avarage time
user: 2.40189500, system: 0.00000000, total: 2.40189500, real: 2.41995030
I, [2021-02-11T17:18:45.521387 #1]  INFO -- : 
report def index instance method: current time
user: 2.40906800, system: 0.00026500, total: 2.40933300, real: 3.43638710
report def index instance method: total time for 1 times called
user: 2.40906800, system: 0.00026500, total: 2.40933300, real: 3.43638710
report def index instance method: avarage time
user: 2.40906800, system: 0.00026500, total: 2.40933300, real: 3.43638710

通常通りの戻り値を返しつつ、裏でこんな感じのログが出力されるようになった。
（current timeがメソッドが実行されたときのタイム。total timeがプロセス起動中に二回以上同じメソッドが実行された際の総タイム。avarage timeが回数/合計の平均タイム）
とりあえずのタイムは手軽に測れるようになり、勉強にもなったので良しとする。

失敗談

製作を始めた時点では（調査不足で）気づいていなかったが、似たような発想のgemは既にあった。
https://github.com/igorkasyanchuk/benchmark_methods

機能面でいくつか異なる点もあり自分のやりたいことは自分のgemが実現したが、車輪の再発明感は否めなかった。

Railsで使用されるメソッドを自動でベンチマークするgemを作ってみた話

背景

実演

失敗談