Latest changes in Rails 7 allows benchmark method to be called from anywhere.
Before
Before this change, we could use it in views or controllers.
<% benchmark '=== Processing invoices ===' do %>
<%= process_invoices %>
<% end %>
But, if we have to benchmark some methods in models or services we needed to do something like this:
require 'benchmark'
def process
logger.info("=== Processing invoices ===")
logger.info Benchmark.measure { process_invoices }
# or
logger.info Benchmark.realtime { process_invoices }
end
This would log the details in the following way.
=== Processing invoices ===
0.406537 0.082624 0.489161 ( 0.503110)
0.5047359999734908
We could also use the following way to log the time taken by the specific method or a code. The only problem is every time we need to benchmark we have to include the module in the class.
mattr_accessor :logger, default: Rails.logger
extend ActiveSupport::Benchmarkable
include ActiveSupport::Benchmarkable
def process
benchmark("=== Processing invoices ===") { process_invoices }
end
The above snippet will log the time taken by the operation:
Started GET "/companies/1/invoices" for ::1 at 2021-02-24 16:38:59 +0530
Processing by CompaniesController#invoices as HTML
Parameters: {"id"=>"1"}
=== Processing invoices === (402.1ms)
Rendered companies/invoices.html.erb within layouts/application (Duration: 1.5ms | Allocations: 426)
Rendered layout layouts/application.html.erb (Duration: 13.0ms | Allocations: 4003)
Completed 200 OK in 427ms (Views: 14.3ms | ActiveRecord: 1.0ms | Allocations: 7079)
After
After this change, we can use the benchmark method anywhere. Now we don’t need to include any modules just for the purpose of benchmarking.
def process
Rails.benchmark("=== Processing invoices ===") do
logger.debug("=== Processing started ===")
process_invoices
logger.debug("=== Processing done ===")
end
end
This will print the output in the logs depending on the log level (default log level is :info
).
Started GET "/companies/1/invoices" for ::1 at 2021-02-24 16:40:35 +0530
Processing by CompaniesController#invoices as HTML
Parameters: {"id"=>"1"}
=== Processing started ===
=== Processing done ===
=== Processing invoices === (400.7ms)
Rendered companies/invoices.html.erb within layouts/application (Duration: 1.1ms | Allocations: 426)
[Webpacker] Everything's up-to-date. Nothing to do
Rendered layout layouts/application.html.erb (Duration: 7.6ms | Allocations: 4025)
Completed 200 OK in 417ms (Views: 8.3ms | ActiveRecord: 0.9ms | Allocations: 7397)
The benchmark
method also accepts two options
-
level
We can set the log level to
:debug
,:info
,:warn
or:error
to ensure the details only show up in specific environments. The default log level value is:info
. -
silence
This option will silence all log activity from within the block (except the benchmark timing information).
Example
def process
Rails.benchmark("=== Processing invoices ===", level: :debug, silence: true) do
logger.debug("=== This won't be logged ===")
process_invoices
logger.debug("=== This won't be logged ===")
end
end
The above method will print the time taken by the expensive operation with log level :debug
.
Any other logs inside the Rails.benchmark
block won’t be shown in the server logs.
In our case, the first and last line inside the Rails.benchmark
block won’t be printed.
Started GET "/companies/1/invoices" for ::1 at 2021-02-24 16:13:44 +0530
Processing by CompaniesController#invoices as HTML
Parameters: {"id"=>"1"}
=== Processing invoices === (404.6ms)
Rendered companies/invoices.html.erb within layouts/application (Duration: 3.4ms | Allocations: 1111)
[Webpacker] Everything's up-to-date. Nothing to do
Rendered layout layouts/application.html.erb (Duration: 18.5ms | Allocations: 7370)
Completed 200 OK in 458ms (Views: 22.7ms | ActiveRecord: 0.9ms | Allocations: 14473)