Automatically benchmarks the methods used in Rails

daiki shibata — Fri, 12 Feb 2021 06:23:33 +0000

I had a job to speed up an application written in Rails.
I wanted to proceed with trial and error while easily benchmarking various methods.

At first, I tried to benchmark the method using the benchmark library. (The profiler uses 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

For example, if you perform an index action this way, you'll see the following log, where you can benchmark the index action, but if you want to benchmark multiple methods and actions, you'll have to add code each time, which is tedious. I also wanted to keep the logs in a log file.

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

Also, if you enclose the processing content you want to measure in Benchmark.bm do ~ end, the return value of that processing part becomes a benchmark object, so cannot use this method if you want to use the return value in another method.

# 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

So I made a gem that seems to solve these problems after studying.
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

If you prepare like this and hit the index action

# 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

Such a log is automatically output. and method then returns the normal return value.
(current time is the time when the method is executed. total time is the total time when the same method is executed more than once during process startup. avarage time is the number of times / total average time)

This made my job a little easier.

(Failure story)

I didn't realize it when I started making it (due to lack of research), but there was already a gem of a similar idea.
https://github.com/igorkasyanchuk/benchmark_methods

DEV Community: daiki shibata

Automatically benchmarks the methods used in Rails