Is default rails controller#action execution time reliable and correct?

user_1735921 0
Viewed 371

to test my time of execution I use this code:

ActiveSupport::Notifications.subscribe 'process_action.action_controller' do |*args|
  event = ActiveSupport::Notifications::Event.new(*args)
  puts "Event received: #{event.duration}"
end

For a request which takes 137ms , it shows just 34ms but I saw in postman and pingdom it takes 137ms.

So where is rest of the 100ms time taking?

See in screenshot: Rails Log

It says the request took 25ms, but in post man it took 90ms, so where did the rest of 65ms went?

I know its because of network and internet speed also matters for complete render.

I just wanna confirm that this is the correct time or something is missing here, for example if ApplicationController has a filter:

before_action :method_name

Then is it considering the action "method_name" also or just the current action ?

performance-testing ruby-on-rails
1 Answers

So where is rest of the 100ms time taking?

Latency. It takes time for request to travel from your postman (or pingdom) instance to the server (and back). Rails server has no way of knowing about these delays (in fact, they don't exist as far as it is concerned), therefore it doesn't include them.

Regarding your screenshot:

Rails Log

It doesn't include any before_action or such filters of the controller. So if your filters are taking time, they won't be considered in this.

So you should use this:

ActiveSupport::Notifications.subscribe 'process_action.action_controller' do |*args|
  event = ActiveSupport::Notifications::Event.new(*args)
  puts "Event received: #{event.duration}"
end

This will include the time spent in filters also.

user_1258160
Related