Rails 7 allows benchmark method to be called from anywhere

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)