Active Support Instrumentation

Topics

• What is Active Support Instrumentation?
• Why you should care
• How it works
• Hooks/Events provided by Rails
• What you can do with it
• Apps using Instrumentation

​

Introduction to Instrumentation

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.
• Looks like Pub/Sub pattern where developers can subscribe to the events published.

Why you should care

• Provides simple, flexible messaging system for instrumenting.
• Lots of valuable data is already published by Rails’ built in instrumentation.
• Provides an easy path for performance monitoring what you care about in your application
• Log & track what matters to you

How it works

• #subscribe - method to subscribe events. Asks to receive instrument data.
• #instrument - method to publish events.

How it works

require 'active_support/notifications'

​

# set up a subscriber callback for a custom event

ActiveSupport::Notifications.subscribe 'events.created_for_test' do |*args|

# get all informations for this event and log/measure it.

end

​

# publish the custom event

ActiveSupport::Notifications.instrument 'events.created_for_test', greeting: 'hello'

#instrument

ActiveSupport::Notifications.instrument 'events.created_for_test', greeting: 'hello'

​

​

Message Name

(What you #subscribe to)

#instrument

ActiveSupport::Notifications.instrument 'events.created_for_test', greeting: 'hello'

​

​

Message Name Extra Arguments

(What you #subscribe to) (Passed as payload to #subscribe)

#instrument

ActiveSupport::Notifications.instrument 'events.created_for_test', greeting: 'hello'

​

​

Message Name Extra Arguments

(What you #subscribe to) (Passed as payload to #subscribe)

# instrument message data - name, start, end, id, payload

=> ["events.created_for_test", 2020-02-04 09:34:15 +0545, 2020-02-04 09:34:16 +0545, fd4ce7289121a48aa266, {:greeting => "hello"}]

​

#instrument (block form)

ActiveSupport::Notifications.instrument 'events.created_for_test', greeting: 'hello' do

puts 'inside block'

end

​

​

#subscribe

ActiveSupport::Notifications.subscribe 'events.created_for_test' do |*args|

name, start, ending, transaction_id, payload = args

duration = (ending - start) * 1000

# log or process payload...

end

​

​

#subscribe

ActiveSupport::Notifications.subscribe 'events.created_for_test' do |*args|

event = ActiveSupport::Notifications::Event.new(*args)

event.name # "events.created_for_test"

event.time # start time

event.end # end time

event.duration

event.transaction_id # unique id

event.payload # {:greeting => "hello"}

# log or process payload...

end

#subscribe (using regular expression)

# subscribe to any event with 'test' in the name

ActiveSupport::Notifications.subscribe /test/ do |*args|

event = ActiveSupport::Notifications::Event.new(*args)

event.name # 'events.created_for_test' or 'testing' or 'events.no_testing'

end

​

Rails instrumentation

# ActionController

start_processing.action_controller

process_action.action_controller

send_file.action_controller

send_data.action_controller

redirect_to.action_controller

halted_callback.action_controller

​

Rails instrumentation

# ActionView

render_template.action_view

render_partial.action_view

​

# ActiveRecord

sql.active_record

instantiation.active_record

​

# ActionMailer

deliver.action_mailer

receive.action_mailer

process_action.action_controller (payload)

Performance Monitoring

ActiveSupport::Notifications.subscribe /process_action.action_controller/ do |*args|

event = ActiveSupport::Notifications::Event.new(*args)

payload = event.payload

controller = payload[:controller]

action = payload[:controller]

format = payload[:format]

status = payload[:status]

db_time = payload[:db_runtime]

view_time = payload[:view_runtime]

total_time = event.duration

end

​

Performance Monitoring

​

​

Started GET "/food_categories" for ::1 at 2020-02-04 12:10:11 +0545

Processing by FoodCategoriesController#index as HTML

Completed 200 OK in 50ms (Views: 30.0ms | ActiveRecord: 0.0ms | Allocations: 23285)

SQL Monitoring

ActiveSupport::Notifications.subscribe 'sql.active_record' do |*args|

event = ActiveSupport::Notifications::Event.new(*args)

payload = event.payload

​

name = payload[:name] # SQL: INSERTs and DELETEs,

# nil: UPDATEs, BEGIN, COMMIT

# <Model> Load, <Model> Exists: SELECTs

duration = event.duration # query duration

sql = payload[:sql] # SQL query

binds = payload[:binds] # bind variables

​

puts "name: #{name}"

puts "duration: #{duration}"

puts "sql: #{sql}"

print "binds: "; pp binds

end

SQL Monitoring

irb(main):044:0> User.last

User Load (0.6ms) SELECT "users".* FROM "users" ORDER BY "users"."id" DESC LIMIT $1 [["LIMIT", 1]]

name: User Load

duration: 0.747

sql: SELECT "users".* FROM "users" ORDER BY "users"."id" DESC LIMIT $1

binds: [#<ActiveModel::Attribute::WithCastValue:0x00007f7f956eead0

@name="LIMIT",

@original_attribute=nil,

@type=

#<ActiveModel::Type::Value:0x00007f7f941a5ea8

@limit=nil,

@precision=nil,

@scale=nil>,

@value=1,

@value_before_type_cast=1>]

=> #<User id: "aacae670-be78-4715-b846-05d8c07a18a3", provider: "email", uid: "user@gmail.com", role: "customer">

​

​

What we can do?

Custom Logging

# Write to log

ActiveSupport::Notifications.subscribe 'events.created_for_test' do |*args|

event = ActiveSupport::Notifications::Event.new(*args)

payload = event.payload

Rails.logger.info "#{payload[:greeting]} Tracked your test here."

end

​

New Relic Tracking

ActiveSupport::Notifications.subscribe 'events.created_for_test' do |*args|

event = ActiveSupport::Notifications::Event.new(*args)

engine = NewRelic::Agent.agent.stats_engine

stat = engine.get_stats_no_scope('Test/Event')

stat.record_data_point(event.duration)

end

​

and more...

• Google Analytics events
• Schedule background jobs
• Fire web hooks

#unsubscribe

# create a subscription

test_event = ActiveSupport::Notifications.subscribe 'events.created_for_test' do |*args|

# do something

end

​

# unsubscribe

ActiveSupport::Notifications.unsubscribe(test_event)

​

​

Simplifying Repetitive Instrumentation

Forward it..

class ApplicationController < ActionController::Base

extend Forwardable

​

def_delegator ActiveSupport::Notifications, :instrument

end

​

class UsersController < ApplicationController

def create

instrument 'user.signup'

end

end

​

​

​

Simplifying Repetitive Subscribers

LogSubscriber

ActiveSupport::Notifications.subscribe 'user.signup' do |*args|

payload = args.last

Rails.logger.info ”new user signup: #{payload[:email]}”

end

​

ActiveSupport::Notifications.subscribe 'user.login' do |*args|

payload = args.last

Rails.logger.info ”user login: #{payload[:user_id]}”

end

​

ActiveSupport::Notifications.subscribe 'user.logout' do |*args|

payload = args.last

Rails.logger.info ”user logout: #{payload[:user_id]}”

end

​

LogSubscriber

ActiveSupport::Notifications.subscribe 'signup.user' do |*args|

payload = args.last

Rails.logger.info ”new user signup: #{payload[:email]}”

end

​

ActiveSupport::Notifications.subscribe 'login.user' do |*args|

payload = args.last

Rails.logger.info ”user login: #{payload[:user_id]}”

end

​

ActiveSupport::Notifications.subscribe 'logout.user' do |*args|

payload = args.last

Rails.logger.info ”user logout: #{payload[:user_id]}”

end

​

LogSubscriber

class UserLogger < ActiveSupport::LogSubscriber

def signup(event) # signup.user

info "new user signup: #{event.payload[:email]}"

end

​

def login(event) # login.user

info "user login: #{event.payload[:user_id]}"

end

​

def logout(event) # logout.user

info "user logout: #{event.payload[:user_id]}"

end

end

UserLogger.attach_to :user

​

​

Thank You!