ActiveSupport::Notifications
There is the old adage, “If a tree falls in the woods, did anyone hear it?” though I would like to suggest a new one, “If it’s not measured did it really happen?” and as someone who works in ops this appeals to me. In ops we work on facts and figures. When we are faced with a problem the first thing we do is look for metrics to see just what is going on.
Why use notifications?
There are many third party tools out there which can be used, but there is also much which the rails framework itself provides. One oft underused parts of rails is ActiveSupport::Notifications which allow for, you guessed it, notifications when standard actions occur. These notifications include but are not limited to:
- start_processing.action_controller
- process_action.action_controller
- render_partial.action_view
- sql.active_record
They all follow a naming convention and are explained in the rails guide including the data that is sent with each notification.
By being notified of when these events occur we can start to record the metrics and identify what is happening. Moving from the realm of theory to that of practice, let’s ask ourselves the question of “Why is our page so slow?” and see how we can use notifications to get the metrics we require.
Subscribing to a notification
Before we show the code for subscribing, we need to know what notification we are wanting to observe. We could listen to all notifications, but that is going to be too noisy. Something such as ‘render_partial.action_view’ is good, but it is only part of a page load so we can leave that to later. What we want to subscribe to is ‘process_action.action_controller’ as that is sent once an action gets called. These actions could be GET, POST, et cetera.
The documentation also gives us a guide to the data we will get from the notification:
- :controller –> The controller name
- :action –> The action
- :params –> Hash of request parameters without any filtered parameter
- :format –> html/js/json/xml etc
- :method –> HTTP request verb
- :path –> Request path
- :view_runtime –> Amount spent in view in ms
- :db_runtime –> Database execution time
This is everything we need to know to start identifying what’s happening when the page loads. We can start looking at the question “Why is our page so slow?”. Particularly we get the time to render the view and the amount of time that the database takes to execute.
ruby
ActiveSupport::Notifications.subscribe /process_action.action_controller/ do |name, start, finish, id, payload|
Rails.logger.debug(["notification:", name, start, finish, id, payload].join(" "))
end
Now that looks fairly simple and it is. Place it into an initializer such as config/initializers/notifications.rb and watch the output in the console as you visit pages in your browser.
Having output in a log file is good, it’s a record of what’s happened in your app. But what happens when you have 10’s of thousands of lines of logs to go through and that is just for a day? Well, you need something else. You need to store these values in something that makes sense and is searchable. For these statistics, a time series database is the perfect solution. There are many you can choose from though to make it easy, something such as TempoDB http://tempo-db.com is ideal. They have a free tier and they have a well documented api to use. They provide a ruby gem tempodb which is used in the example. Add it to your Gemfile and run ‘bundle install’ to get it going.
To get the details sent through to TempoDB you will need to have a subscriber that looks like:
ruby
ActiveSupport::Notifications.subscribe /process_action.action_controller/ do |name, start, finish, id, payload|
if Rails.env.production? || Rails.env.development?
client = TempoDB::Client.new(ENV["TEMPO_API_KEY"], ENV["TEMPO_API_SECRET"])
params = payload[:params]
base_key = "#{Rails.env}.#{params["controller"]}.#{params["action"]}"
db_runtime_key = "#{base_key}.db_runtime"
view_runtime_key = "#{base_key}.view_runtime"
status_key = "#{base_key}.status.#{payload[:status]}"
db_value = payload[:db_runtime]
view_value = payload[:view_runtime]
client.write_key(db_runtime_key, [TempoDB::DataPoint.new(Time.now.utc, db_value)]) unless db_value == 0
client.write_key(view_runtime_key, [TempoDB::DataPoint.new(Time.now.utc, view_value)])
client.increment_key(status_key, [TempoDB::DataPoint.new(Time.now.utc, 1)]) unless payload[:status].nil?
end
end
That will create three keys in your database which hold data for the view_runtime, db_runtime and the occurrence of the status code at the time interval. By saving these values in TempoDB we are able to observe their change over time as well as abnormalities. This is something amazing and gives us a powerful tool for making our app run fast.
But that’s not all ActiveSupport::Notifications can do. You can use it to instrument custom parts of your app as well.
How can I instrument?
Say the product owner came to you and said “I want to know when people searched for the special of the month on our site”. Okay, simple enough request. But the problem is that the special changes each month and it’s far more practical to do a comparison of terms and see how they stack up against each other. As a good developer, you understand what your ops team is up to and know that they have been using ActiveSupport::Notifications to get statistics out of the app for a while. You instantly think “can I do the same for this request?”. Well yes, developer, you can. Say you have a controller called Products which has a search method. That method is passed some params which is a hash. Within the search method you could add:
ruby
ActiveSupport::Notifications.instrument "search.product", search: :params
Within your initializer you would then subscribe to the notification like:
ruby
ActiveSupport::Notifications.subscribe "search.product" do |name, started, finished, unique_id, data|
puts data.inspect # {search: :params}
end
There you have it, you now have a custom notification that is sent every time you search for a product. You also subscribe to that data and display it to the console using puts. It is left as an exercise for the reader as to how you want to persist the data you get from the custom notification.
Making sense of it all
Returning to our initial question of “Why is the page slow?” we are now equipped with a powerful tool for identifying why the page is just so slow. Having run some traffic against our site, we are able to observe the notifications generated and look at the data which is stored in our database. If these statistics prove our page is indeed slow, we can then start asking more specific questions. We can see just how long database queries take and begin to optimise our app based upon data rather than feeling.
Caveats and final words
Notifications are amazing things which allow us to do a lot. Though some may be tempted to think that notifications are a good way of creating flow within your app. Like exceptions, this isn’t the case. Notifications are there so you are told when an action occurs, not to provide you a way of acting upon success / failure. The best use of Notifications is to log statistics and provide insight to your app.
This though, is just the tip of the iceberg. There is so much awesome stuff which ActiveSupport::Notifications allow you to do. Here are some great links for more information:
