Measuring sql query time of a piece of code using ActiveSupport::Notifications

ActiveSupport::Notifications provides an instrumentation API for Ruby. It is used throughout rails to publish instrumentation events that include information about each part of a request/response cycle.

Have a look at your application log file - yes, those are those events. The cool thing is that you can subscribe to those events.

There is also a convenience method that allows you to subscribe to those events only for the time of executing a block of code. Thus you can capture all sql queries that are triggered when executing your block. Now all you have to do is sum up the duration and you will know how much time was lost in the database for that particular snippet of code.

Copyevents = []

callback = lambda do |*args|  
  # init ActiveSupport::Notifications::Events from your payload so you can query your data nicely
  event = ActiveSupport::Notifications::Event.new(*args)
  events << event
end

# subscribe to active record sql events

ActiveSupport::Notifications.subscribed(callback, "sql.active_record") do
  # the code you want to analyze ...
  Tv.generate_schedule!
end

p events.sum(&:duration)