Rails에서 사용되는 방법을 자동으로 벤치마킹합니다.

저는 Rails로 작성된 애플리케이션의 속도를 높이는 일을 했습니다.
다양한 방법을 쉽게 벤치마킹하면서 시행착오를 해보고 싶었다.

처음에는 benchmark library 을 사용하여 방법을 벤치마킹하려고 했습니다. (프로파일러는 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

예를 들어 이러한 방식으로 인덱스 작업을 수행하면 인덱스 작업을 벤치마킹할 수 있는 다음 로그가 표시되지만 여러 메서드와 작업을 벤치마킹하려면 매번 코드를 추가해야 합니다. 지루하다. 또한 로그를 로그 파일에 보관하고 싶었습니다.

                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
    # The return value is not the value of @old_cars but the object of the measurement result
    # => [#<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
  # (Omitted)
end

그래서 공부를 하고 나서 이러한 문제를 해결할 수 있을 것 같은 보석을 만들었습니다.
https://github.com/shibatadaiki/Rbenchmarker

# config/environments/development.rb
require "active_support/core_ext/integer/time"
Rails.application.configure do
  config.eager_load = true # change setting to true
  config.after_initialize do # Add settings
    Rbenchmarker.setup switch:'on', output_log_path: nil, except_classes: [], except_modules: []
  end
  # (Omitted)
end

# sample_controller.rb
class OldCarsController < ApplicationController
  rbenchmarker all: __FILE__ # Add description
  def index
  # (Omitted)
end

이렇게 준비하고 인덱스 액션을 치면

# 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는 횟수/총 평균 시간)

이것은 내 작업을 조금 더 쉽게 만들었습니다.

(실패 사례)

(연구 부족으로 인해) 만들기 시작할 때는 몰랐지만 이미 비슷한 아이디어의 보석이 있었습니다.
https://github.com/igorkasyanchuk/benchmark_methods