Active Support Instrumentation

Active Support is a part of core Rails that provides Ruby language extensions, utilities, and other things. One of the things it includes is an instrumentation API that can be used inside an application to measure certain actions that occur within Ruby code, such as that inside a Rails application or the framework itself. It is not limited to Rails, however. It can be used independently in other Ruby scripts if it is so desired.

In this guide, you will learn how to use the instrumentation API inside of Active Support to measure events inside of Rails and other Ruby code.

After reading this guide, you will know:

• What instrumentation can provide.
• How to add a subscriber to a hook.
• The hooks inside the Rails framework for instrumentation.
• How to build a custom instrumentation implementation.

The instrumentation API provided by Active Support allows developers to provide hooks which other developers may hook into. There are several of these within the Rails framework. With this API, developers can choose to be notified when certain events occur inside their application or another piece of Ruby code.

For example, there is a hook provided within Active Record that is called every time Active Record uses an SQL query on a database. This hook could be subscribed to, and used to track the number of queries during a certain action. There’s another hook around the processing of an action of a controller. This could be used, for instance, to track how long a specific action has taken.

You are even able to create your own events inside your application which you can later subscribe to.

Subscribing to an event is easy. Use ActiveSupport::Notifications.subscribe with a block to listen to any notification.

The block receives the following arguments:

• The name of the event
• Time when it started
• Time when it finished
• A unique ID for the instrumenter that fired the event
• The payload (described in future sections)

ActiveSupport::Notifications.subscribe "process_action.action_controller" do |name, started, finished, unique_id, data|
  # your own custom stuff
  Rails.logger.info "#{name} Received! (started: #{started}, finished: #{finished})" # process_action.action_controller Received (started: 2019-05-05 13:43:57 -0800, finished: 2019-05-05 13:43:58 -0800)
end

If you are concerned about the accuracy of started and finished to compute a precise elapsed time then use ActiveSupport::Notifications.monotonic_subscribe. The given block would receive the same arguments as above but the started and finished will have values with an accurate monotonic time instead of wall-clock time.

ActiveSupport::Notifications.monotonic_subscribe "process_action.action_controller" do |name, started, finished, unique_id, data|
  # your own custom stuff
  Rails.logger.info "#{name} Received! (started: #{started}, finished: #{finished})" # process_action.action_controller Received (started: 1560978.425334, finished: 1560979.429234)
end

Defining all those block arguments each time can be tedious. You can easily create an ActiveSupport::Notifications::Event from block arguments like this:

ActiveSupport::Notifications.subscribe "process_action.action_controller" do |*args|
  event = ActiveSupport::Notifications::Event.new *args

  event.name      # => "process_action.action_controller"
  event.duration  # => 10 (in milliseconds)
  event.payload   # => {:extra=>information}

  Rails.logger.info "#{event} Received!"
end

You may also pass a block that accepts only one argument, and it will receive an event object:

ActiveSupport::Notifications.subscribe "process_action.action_controller" do |event|
  event.name      # => "process_action.action_controller"
  event.duration  # => 10 (in milliseconds)
  event.payload   # => {:extra=>information}

  Rails.logger.info "#{event} Received!"
end

Most times you only care about the data itself. Here is a shortcut to just get the data.

ActiveSupport::Notifications.subscribe "process_action.action_controller" do |*args|
  data = args.extract_options!
  data # { extra: :information }
end

You may also subscribe to events matching a regular expression. This enables you to subscribe to multiple events at once. Here’s how to subscribe to everything from ActionController.

ActiveSupport::Notifications.subscribe /action_controller/ do |*args|
  # inspect all ActionController events
end

Within the Ruby on Rails framework, there are a number of hooks provided for common events. These are detailed below.

{
  key: 'posts/1-dashboard-view'
}

{
  key: 'posts/1-dashboard-view'
}

{
  key: 'posts/1-dashboard-view'
}

{
  key: 'posts/1-dashboard-view'
}

{
  controller: "PostsController",
  action: "new",
  params: { "action" => "new", "controller" => "posts" },
  headers: #<ActionDispatch::Http::Headers:0x0055a67a519b88>,
  format: :html,
  method: "GET",
  path: "/posts/new"
}

{
  controller: "PostsController",
  action: "index",
  params: {"action" => "index", "controller" => "posts"},
  headers: #<ActionDispatch::Http::Headers:0x0055a67a519b88>,
  format: :html,
  method: "GET",
  path: "/posts",
  request: #<ActionDispatch::Request:0x00007ff1cb9bd7b8>,
  response: #<ActionDispatch::Response:0x00007f8521841ec8>,
  status: 200,
  view_runtime: 46.848,
  db_runtime: 0.157
}

INFO. Additional keys may be added by the caller.

ActionController does not add any specific information to the payload. All options are passed through to the payload.

{
  status: 302,
  location: "http://localhost:3000/posts/new",
  request: #<ActionDispatch::Request:0x00007ff1cb9bd7b8>
}

{
  filter: ":halting_filter"
}

{
  identifier: "/Users/adam/projects/notifications/app/views/posts/index.html.erb",
  layout: "layouts/application",
  locals: {foo: "bar"}
}

{
  identifier: "/Users/adam/projects/notifications/app/views/posts/_form.html.erb",
  locals: {foo: "bar"}
}

:cache_hits is only included if the collection is rendered with cached: true.

{
  identifier: "/Users/adam/projects/notifications/app/views/posts/_post.html.erb",
  count: 3,
  cache_hits: 0
}

{
  identifier: "/Users/adam/projects/notifications/app/views/layouts/application.html.erb"
}

INFO. The adapters will add their own data as well.

{
  sql: "SELECT \"posts\".* FROM \"posts\" ",
  name: "Post Load",
  connection: #<ActiveRecord::ConnectionAdapters::SQLite3Adapter:0x00007f9f7a838850>,
  binds: [#<ActiveModel::Attribute::WithCastValue:0x00007fe19d15dc00>],
  type_casted_binds: [11],
  statement_name: nil
}

{
  record_count: 1,
  class_name: "User"
}

{
  mailer: "Notification",
  message_id: "4f5b5491f1774_181b23fc3d4434d38138e5@mba.local.mail",
  subject: "Rails Guides",
  to: ["users@rails.com", "dhh@rails.com"],
  from: ["me@rails.com"],
  date: Sat, 10 Mar 2012 14:18:09 +0100,
  mail: "...", # omitted for brevity
  perform_deliveries: true
}

{
  mailer: "Notification",
  action: "welcome_email",
  args: []
}

This event is only used when #fetch is called with a block.

INFO. Options passed to fetch will be merged with the payload when writing to the store

{
  key: "name-of-complicated-computation",
  store: "ActiveSupport::Cache::MemCacheStore"
}

This event is only used when #fetch is called with a block.

INFO. Options passed to fetch will be merged with the payload.

{
  key: "name-of-complicated-computation",
  store: "ActiveSupport::Cache::MemCacheStore"
}

INFO. Cache stores may add their own keys

{
  key: "name-of-complicated-computation",
  store: "ActiveSupport::Cache::MemCacheStore"
}

{
  key: "name-of-complicated-computation",
  store: "ActiveSupport::Cache::MemCacheStore"
}

{
  key: "name-of-complicated-computation",
  store: "ActiveSupport::Cache::MemCacheStore"
}

INFO. The only ActiveStorage service that provides this hook so far is GCS.

{
  mailbox: #<RepliesMailbox:0x00007f9f7a8388>,
  inbound_email: {
    id: 1,
    message_id: "0CB459E0-0336-41DA-BC88-E6E28C697DDB@37signals.com",
    status: "processing"
  }
}

If an exception happens during any instrumentation the payload will include information about it.

Adding your own events is easy as well. ActiveSupport::Notifications will take care of all the heavy lifting for you. Simply call instrument with a name, payload and a block. The notification will be sent after the block returns. ActiveSupport will generate the start and end times and add the instrumenter’s unique ID. All data passed into the instrument call will make it into the payload.

Here’s an example:

ActiveSupport::Notifications.instrument "my.custom.event", this: :data do
  # do your custom stuff here
end

Now you can listen to this event with:

ActiveSupport::Notifications.subscribe "my.custom.event" do |name, started, finished, unique_id, data|
  puts data.inspect # {:this=>:data}
end

You also have the option to call instrument without passing a block. This lets you leverage the instrumentation infrastructure for other messaging uses.

ActiveSupport::Notifications.instrument "my.custom.event", this: :data

ActiveSupport::Notifications.subscribe "my.custom.event" do |name, started, finished, unique_id, data|
  puts data.inspect # {:this=>:data}
end

You should follow Rails conventions when defining your own events. The format is: event.library. If your application is sending Tweets, you should create an event named tweet.twitter.