배경

거대화 노후화해 온 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을 만들어 보았다.
htps : // 기주 b. 코 m / 잠시 / R ben ch r r

시연

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 가 메서드가 실행되었을 때의 시간
우선의 타임은 간편하게 측정할 수 있게 되어, 공부도 되었으므로 좋다고 한다.

실패담

제작을 시작한 시점에서는 (조사 부족으로) 눈치채지 못했지만, 비슷한 발상의 gem은 이미 있었다.
htps : // 기주 b. 코 m / 이코

기능면에서 몇 가지 다른 점도 있어 자신이 하고 싶은 것은 자신의 젬이 실현했지만, 바퀴의 재발명감은 부정할 수 없었다.