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
Top comments (0)