Stop building AS::Notifications::Event manually

It's possible since Rails 6 (3ea2857943dc294d7809930b4cc5b318b9c39577) to let the framework create Event objects, but the guides and docs weren't updated to lead with this example.

Manually instantiating an Event doesn't record CPU time and allocations, I've seen it more than once that people copy-pasting the example code get confused about these stats returning 0. The tests here show that - just like the apps I've worked on - the old pattern keeps getting copy-pasted.
This commit is contained in:
Bart de Water 2023-09-29 11:34:44 -04:00 committed by Bart de Water
parent d38dcdc009
commit 95b6fbd00f
17 changed files with 108 additions and 164 deletions

@ -200,9 +200,7 @@ def error_handler
test "notification for perform_action" do
events = []
ActiveSupport::Notifications.subscribe "perform_action.action_cable" do |*args|
events << ActiveSupport::Notifications::Event.new(*args)
end
ActiveSupport::Notifications.subscribe("perform_action.action_cable") { |event| events << event }
data = { "action" => :speak, "content" => "hello" }
@channel.perform_action data
@ -218,9 +216,7 @@ def error_handler
test "notification for transmit" do
events = []
ActiveSupport::Notifications.subscribe "transmit.action_cable" do |*args|
events << ActiveSupport::Notifications::Event.new(*args)
end
ActiveSupport::Notifications.subscribe("transmit.action_cable") { |event| events << event }
@channel.perform_action "action" => :get_latest
expected_data = { data: "latest" }
@ -238,9 +234,7 @@ def error_handler
@channel.subscribe_to_channel
events = []
ActiveSupport::Notifications.subscribe "transmit_subscription_confirmation.action_cable" do |*args|
events << ActiveSupport::Notifications::Event.new(*args)
end
ActiveSupport::Notifications.subscribe("transmit_subscription_confirmation.action_cable") { |e| events << e }
@channel.stub(:subscription_confirmation_sent?, false) do
@channel.send(:transmit_subscription_confirmation)
@ -255,9 +249,7 @@ def error_handler
test "notification for transmit_subscription_rejection" do
events = []
ActiveSupport::Notifications.subscribe "transmit_subscription_rejection.action_cable" do |*args|
events << ActiveSupport::Notifications::Event.new(*args)
end
ActiveSupport::Notifications.subscribe("transmit_subscription_rejection.action_cable") { |event| events << event }
@channel.send(:transmit_subscription_rejection)

@ -16,9 +16,7 @@ class BroadcastingTest < ActionCable::TestCase
server = TestServer.new
events = []
ActiveSupport::Notifications.subscribe "broadcast.action_cable" do |*args|
events << ActiveSupport::Notifications::Event.new(*args)
end
ActiveSupport::Notifications.subscribe("broadcast.action_cable") { |event| events << event }
broadcasting = "test_queue"
message = { body: "test message" }
@ -37,9 +35,7 @@ class BroadcastingTest < ActionCable::TestCase
server = TestServer.new
events = []
ActiveSupport::Notifications.subscribe "broadcast.action_cable" do |*args|
events << ActiveSupport::Notifications::Event.new(*args)
end
ActiveSupport::Notifications.subscribe("broadcast.action_cable") { |event| events << event }
broadcasting = "test_queue"
message = { body: "test message" }

@ -8,9 +8,7 @@ class RepliesMailbox < ActionMailbox::Base
class ActionMailbox::Base::NotificationsTest < ActiveSupport::TestCase
test "instruments processing" do
events = []
ActiveSupport::Notifications.subscribe("process.action_mailbox") do |*args|
events << ActiveSupport::Notifications::Event.new(*args)
end
ActiveSupport::Notifications.subscribe("process.action_mailbox") { |event| events << event }
mailbox = RepliesMailbox.new(create_inbound_email_from_fixture("welcome.eml"))
mailbox.perform_processing

@ -965,9 +965,7 @@ def a_callback
test "notification for process" do
events = []
ActiveSupport::Notifications.subscribe("process.action_mailer") do |*args|
events << ActiveSupport::Notifications::Event.new(*args)
end
ActiveSupport::Notifications.subscribe("process.action_mailer") { |event| events << event }
BaseMailer.welcome(body: "Hello there").deliver_now
@ -982,9 +980,7 @@ def a_callback
test "notification for deliver" do
events = []
ActiveSupport::Notifications.subscribe("deliver.action_mailer") do |*args|
events << ActiveSupport::Notifications::Event.new(*args)
end
ActiveSupport::Notifications.subscribe("deliver.action_mailer") { |event| events << event }
BaseMailer.welcome(body: "Hello there").deliver_now

@ -173,9 +173,8 @@ def test_fragment_cache_instrumentation
@mailer.enable_fragment_cache_logging = true
payload = nil
subscriber = proc do |*args|
event = ActiveSupport::Notifications::Event.new(*args)
payload = event.payload
subscriber = proc do |_, _, _, _, event_payload|
payload = event_payload
end
ActiveSupport::Notifications.subscribed(subscriber, "read_fragment.action_mailer") do

@ -257,9 +257,8 @@ def test_render_inline_before_fragment_caching
def test_fragment_cache_instrumentation
payload = nil
subscriber = proc do |*args|
event = ActiveSupport::Notifications::Event.new(*args)
payload = event.payload
subscriber = proc do |_, _, _, _, event_payload|
payload = event_payload
end
ActiveSupport::Notifications.subscribed(subscriber, "read_fragment.action_controller") do

@ -195,9 +195,7 @@ def test_delete_works
test "instruments the execution of middlewares" do
events = []
subscriber = proc do |*args|
events << ActiveSupport::Notifications::Event.new(*args)
end
subscriber = proc { |event| events << event }
ActiveSupport::Notifications.subscribed(subscriber, "process_middleware.action_dispatch") do
app = Rack::Lint.new(

@ -89,10 +89,8 @@ class QueuingTest < ActiveSupport::TestCase
jobs = HelloJob.new("Jamie"), HelloJob.new("John")
called = false
subscriber = lambda do |*args|
subscriber = proc do |_, _, _, _, payload|
called = true
event = ActiveSupport::Notifications::Event.new(*args)
payload = event.payload
assert payload[:adapter]
assert_equal jobs, payload[:jobs]
assert_equal 2, payload[:enqueued_count]

@ -358,14 +358,13 @@ class TrilogyAdapterTest < ActiveRecord::TrilogyTestCase
def assert_notification(notification, expected_payload = {}, &block)
notification_sent = false
subscription = lambda do |*args|
subscription = lambda do |_, _, _, _, payload|
notification_sent = true
event = ActiveSupport::Notifications::Event.new(*args)
expected_payload.each do |key, value|
assert(
value === event.payload[key],
"Expected notification payload[:#{key}] to match #{value.inspect}, but got #{event.payload[key].inspect}."
value === payload[key],
"Expected notification payload[:#{key}] to match #{value.inspect}, but got #{payload[key].inspect}."
)
end
end

@ -11,10 +11,9 @@ def setup
def test_payload_name_on_load
Book.create(name: "test book")
subscriber = ActiveSupport::Notifications.subscribe("sql.active_record") do |*args|
event = ActiveSupport::Notifications::Event.new(*args)
if event.payload[:sql].match?("SELECT")
assert_equal "Book Load", event.payload[:name]
subscriber = ActiveSupport::Notifications.subscribe("sql.active_record") do |_, _, _, _, payload|
if payload[:sql].match?("SELECT")
assert_equal "Book Load", payload[:name]
end
end
Book.first
@ -23,10 +22,9 @@ def test_payload_name_on_load
end
def test_payload_name_on_create
subscriber = ActiveSupport::Notifications.subscribe("sql.active_record") do |*args|
event = ActiveSupport::Notifications::Event.new(*args)
if event.payload[:sql].match?("INSERT")
assert_equal "Book Create", event.payload[:name]
subscriber = ActiveSupport::Notifications.subscribe("sql.active_record") do |_, _, _, _, payload|
if payload[:sql].match?("INSERT")
assert_equal "Book Create", payload[:name]
end
end
Book.create(name: "test book")
@ -35,10 +33,9 @@ def test_payload_name_on_create
end
def test_payload_name_on_update
subscriber = ActiveSupport::Notifications.subscribe("sql.active_record") do |*args|
event = ActiveSupport::Notifications::Event.new(*args)
if event.payload[:sql].match?("UPDATE")
assert_equal "Book Update", event.payload[:name]
subscriber = ActiveSupport::Notifications.subscribe("sql.active_record") do |_, _, _, _, payload|
if payload[:sql].match?("UPDATE")
assert_equal "Book Update", payload[:name]
end
end
book = Book.create(name: "test book", format: "paperback")
@ -48,10 +45,9 @@ def test_payload_name_on_update
end
def test_payload_name_on_update_all
subscriber = ActiveSupport::Notifications.subscribe("sql.active_record") do |*args|
event = ActiveSupport::Notifications::Event.new(*args)
if event.payload[:sql].match?("UPDATE")
assert_equal "Book Update All", event.payload[:name]
subscriber = ActiveSupport::Notifications.subscribe("sql.active_record") do |_, _, _, _, payload|
if payload[:sql].match?("UPDATE")
assert_equal "Book Update All", payload[:name]
end
end
Book.update_all(format: "ebook")
@ -60,10 +56,9 @@ def test_payload_name_on_update_all
end
def test_payload_name_on_destroy
subscriber = ActiveSupport::Notifications.subscribe("sql.active_record") do |*args|
event = ActiveSupport::Notifications::Event.new(*args)
if event.payload[:sql].match?("DELETE")
assert_equal "Book Destroy", event.payload[:name]
subscriber = ActiveSupport::Notifications.subscribe("sql.active_record") do |_, _, _, _, payload|
if payload[:sql].match?("DELETE")
assert_equal "Book Destroy", payload[:name]
end
end
book = Book.create(name: "test book")
@ -73,10 +68,9 @@ def test_payload_name_on_destroy
end
def test_payload_name_on_delete_all
subscriber = ActiveSupport::Notifications.subscribe("sql.active_record") do |*args|
event = ActiveSupport::Notifications::Event.new(*args)
if event.payload[:sql].match?("DELETE")
assert_equal "Book Delete All", event.payload[:name]
subscriber = ActiveSupport::Notifications.subscribe("sql.active_record") do |_, _, _, _, payload|
if payload[:sql].match?("DELETE")
assert_equal "Book Delete All", payload[:name]
end
end
Book.delete_all
@ -85,10 +79,9 @@ def test_payload_name_on_delete_all
end
def test_payload_name_on_pluck
subscriber = ActiveSupport::Notifications.subscribe("sql.active_record") do |*args|
event = ActiveSupport::Notifications::Event.new(*args)
if event.payload[:sql].match?("SELECT")
assert_equal "Book Pluck", event.payload[:name]
subscriber = ActiveSupport::Notifications.subscribe("sql.active_record") do |_, _, _, _, payload|
if payload[:sql].match?("SELECT")
assert_equal "Book Pluck", payload[:name]
end
end
Book.pluck(:name)
@ -97,10 +90,9 @@ def test_payload_name_on_pluck
end
def test_payload_name_on_count
subscriber = ActiveSupport::Notifications.subscribe("sql.active_record") do |*args|
event = ActiveSupport::Notifications::Event.new(*args)
if event.payload[:sql].match?("SELECT")
assert_equal "Book Count", event.payload[:name]
subscriber = ActiveSupport::Notifications.subscribe("sql.active_record") do |_, _, _, _, payload|
if payload[:sql].match?("SELECT")
assert_equal "Book Count", payload[:name]
end
end
Book.count
@ -109,10 +101,9 @@ def test_payload_name_on_count
end
def test_payload_name_on_grouped_count
subscriber = ActiveSupport::Notifications.subscribe("sql.active_record") do |*args|
event = ActiveSupport::Notifications::Event.new(*args)
if event.payload[:sql].match?("SELECT")
assert_equal "Book Count", event.payload[:name]
subscriber = ActiveSupport::Notifications.subscribe("sql.active_record") do |_, _, _, _, payload|
if payload[:sql].match?("SELECT")
assert_equal "Book Count", payload[:name]
end
end
Book.group(:status).count
@ -122,9 +113,8 @@ def test_payload_name_on_grouped_count
def test_payload_connection_with_query_cache_disabled
connection = Book.connection
subscriber = ActiveSupport::Notifications.subscribe("sql.active_record") do |*args|
event = ActiveSupport::Notifications::Event.new(*args)
assert_equal connection, event.payload[:connection]
subscriber = ActiveSupport::Notifications.subscribe("sql.active_record") do |_, _, _, _, payload|
assert_equal connection, payload[:connection]
end
Book.first
ensure
@ -133,9 +123,8 @@ def test_payload_connection_with_query_cache_disabled
def test_payload_connection_with_query_cache_enabled
connection = Book.connection
subscriber = ActiveSupport::Notifications.subscribe("sql.active_record") do |*args|
event = ActiveSupport::Notifications::Event.new(*args)
assert_equal connection, event.payload[:connection]
subscriber = ActiveSupport::Notifications.subscribe("sql.active_record") do |_, _, _, _, payload|
assert_equal connection, payload[:connection]
end
Book.cache do
Book.first

@ -129,9 +129,7 @@ def with_raise_on_open_redirects(service)
def subscribe_events_from(name)
events = []
ActiveSupport::Notifications.subscribe(name) do |*args|
events << ActiveSupport::Notifications::Event.new(*args)
end
ActiveSupport::Notifications.subscribe(name) { |event| events << event }
events
end
end

@ -29,6 +29,16 @@ module ActiveSupport
# You can consume those events and the information they provide by registering
# a subscriber.
#
# ActiveSupport::Notifications.subscribe('render') do |event|
# event.name # => "render"
# event.duration # => 10 (in milliseconds)
# event.payload # => { extra: :information }
# event.allocations # => 1826 (objects)
# end
#
# +Event+ objects record CPU time and allocations. If you don't need this
# it's also possible to pass a block that accepts five arguments:
#
# ActiveSupport::Notifications.subscribe('render') do |name, start, finish, id, payload|
# name # => String, name of the event (such as 'render' from above)
# start # => Time, when the instrumented block started execution
@ -42,20 +52,18 @@ module ActiveSupport
#
# ActiveSupport::Notifications.monotonic_subscribe('render') do |name, start, finish, id, payload|
# name # => String, name of the event (such as 'render' from above)
# start # => Monotonic time, when the instrumented block started execution
# finish # => Monotonic time, when the instrumented block ended execution
# start # => Float, monotonic time when the instrumented block started execution
# finish # => Float, monotonic time when the instrumented block ended execution
# id # => String, unique ID for the instrumenter that fired the event
# payload # => Hash, the payload
# end
#
# The +start+ and +finish+ values above represent monotonic time.
#
# For instance, let's store all "render" events in an array:
#
# events = []
#
# ActiveSupport::Notifications.subscribe('render') do |*args|
# events << ActiveSupport::Notifications::Event.new(*args)
# ActiveSupport::Notifications.subscribe('render') do |event|
# events << event
# end
#
# That code returns right away, you are just subscribing to "render" events.
@ -66,14 +74,10 @@ module ActiveSupport
# end
#
# event = events.first
# event.name # => "render"
# event.duration # => 10 (in milliseconds)
# event.payload # => { extra: :information }
#
# The block in the <tt>subscribe</tt> call gets the name of the event, start
# timestamp, end timestamp, a string with a unique identifier for that event's instrumenter
# (something like "535801666f04d0298cd6"), and a hash with the payload, in
# that order.
# event.name # => "render"
# event.duration # => 10 (in milliseconds)
# event.payload # => { extra: :information }
# event.allocations # => 1826 (objects)
#
# If an exception happens during that particular instrumentation the payload will
# have a key <tt>:exception</tt> with an array of two elements as value: a string with
@ -138,7 +142,7 @@ module ActiveSupport
# You can subscribe to some event temporarily while some block runs. For
# example, in
#
# callback = lambda {|*args| ... }
# callback = lambda {|event| ... }
# ActiveSupport::Notifications.subscribed(callback, "sql.active_record") do
# ...
# end
@ -161,7 +165,7 @@ module ActiveSupport
#
# The +subscribe+ method returns a subscriber object:
#
# subscriber = ActiveSupport::Notifications.subscribe("render") do |*args|
# subscriber = ActiveSupport::Notifications.subscribe("render") do |event|
# ...
# end
#
@ -214,11 +218,15 @@ def instrument(name, payload = {})
# You can subscribe to events by passing a String to match exact event
# names, or by passing a Regexp to match all events that match a pattern.
#
# ActiveSupport::Notifications.subscribe(/render/) do |*args|
# @event = ActiveSupport::Notifications::Event.new(*args)
# If the block passed to the method only takes one argument,
# it will yield an +Event+ object to the block:
#
# ActiveSupport::Notifications.subscribe(/render/) do |event|
# @event = event
# end
#
# The +block+ will receive five parameters with information about the event:
# Otherwise the +block+ will receive five arguments with information
# about the event:
#
# ActiveSupport::Notifications.subscribe('render') do |name, start, finish, id, payload|
# name # => String, name of the event (such as 'render' from above)
@ -228,16 +236,9 @@ def instrument(name, payload = {})
# payload # => Hash, the payload
# end
#
# If the block passed to the method only takes one parameter,
# it will yield an event object to the block:
#
# ActiveSupport::Notifications.subscribe(/render/) do |event|
# @event = event
# end
#
# Raises an error if invalid event name type is passed:
#
# ActiveSupport::Notifications.subscribe(:render) {|*args| ...}
# ActiveSupport::Notifications.subscribe(:render) {|event| ...}
# #=> ArgumentError (pattern must be specified as a String, Regexp or empty)
#
def subscribe(pattern = nil, callback = nil, &block)

@ -185,8 +185,8 @@ def parent_of?(event) # :nodoc:
# Returns the difference in milliseconds between when the execution of the
# event started and when it ended.
#
# ActiveSupport::Notifications.subscribe('wait') do |*args|
# @event = ActiveSupport::Notifications::Event.new(*args)
# ActiveSupport::Notifications.subscribe('wait') do |event|
# @event = event
# end
#
# ActiveSupport::Notifications.instrument('wait') do

@ -55,9 +55,7 @@ def with_instrumentation(method)
event_name = "cache_#{method}.active_support"
[].tap do |events|
ActiveSupport::Notifications.subscribe event_name do |*args|
events << ActiveSupport::Notifications::Event.new(*args)
end
ActiveSupport::Notifications.subscribe(event_name) { |event| events << event }
yield
end
ensure

@ -677,9 +677,7 @@ def test_really_long_keys
def test_cache_hit_instrumentation
key = "test_key"
@events = []
ActiveSupport::Notifications.subscribe "cache_read.active_support" do |*args|
@events << ActiveSupport::Notifications::Event.new(*args)
end
ActiveSupport::Notifications.subscribe("cache_read.active_support") { |event| @events << event }
assert @cache.write(key, "1", raw: true)
assert @cache.fetch(key, raw: true) { }
assert_equal 1, @events.length
@ -692,9 +690,7 @@ def test_cache_hit_instrumentation
def test_cache_miss_instrumentation
@events = []
ActiveSupport::Notifications.subscribe(/^cache_(.*)\.active_support$/) do |*args|
@events << ActiveSupport::Notifications::Event.new(*args)
end
ActiveSupport::Notifications.subscribe(/^cache_(.*)\.active_support$/) { |event| @events << event }
assert_not @cache.fetch(SecureRandom.uuid) { }
assert_equal 3, @events.length
assert_equal "cache_read.active_support", @events[0].name

@ -386,9 +386,7 @@ def test_publishing_after_a_new_subscribe_works
@notifier.publish :foo
@notifier.publish :foo
@notifier.subscribe("not_existent") do |*args|
@events << ActiveSupport::Notifications::Event.new(*args)
end
@notifier.subscribe("not_existent") { |event| @events << event }
@notifier.publish :foo
@notifier.publish :foo

@ -29,10 +29,25 @@ You are even able to [create your own events](#creating-custom-events) inside yo
Subscribing to an Event
-----------------------
Subscribing to an event is easy. Use [`ActiveSupport::Notifications.subscribe`][] with a block to
listen to any notification.
Use [`ActiveSupport::Notifications.subscribe`][] with a block to listen to any notification. Depending on the amount of
arguments the block takes, you will receive different data.
The block receives the following arguments:
The first way to subscribe to an event is to use a block with a single argument. The argument will be an instance of
[`ActiveSupport::Notifications::Event`][].
```ruby
ActiveSupport::Notifications.subscribe "process_action.action_controller" do |event|
event.name # => "process_action.action_controller"
event.duration # => 10 (in milliseconds)
event.allocations # => 1826
event.payload # => {:extra=>information}
Rails.logger.info "#{event} Received!"
end
```
If you don't need all the data recorded by an Event object, you can also specify a
block that takes the following five arguments:
* Name of the event
* Time when it started
@ -41,45 +56,19 @@ The block receives the following arguments:
* The payload for the event
```ruby
ActiveSupport::Notifications.subscribe "process_action.action_controller" do |name, started, finished, unique_id, data|
ActiveSupport::Notifications.subscribe "process_action.action_controller" do |name, started, finished, unique_id, payload|
# 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)
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.
```ruby
ActiveSupport::Notifications.monotonic_subscribe "process_action.action_controller" do |name, started, finished, unique_id, data|
ActiveSupport::Notifications.monotonic_subscribe "process_action.action_controller" do |name, started, finished, unique_id, payload|
# 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:
```ruby
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:
```ruby
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!"
duration = finished - started # 1560979.429234 - 1560978.425334
Rails.logger.info "#{name} Received! (duration: #{duration})" # process_action.action_controller Received! (duration: 1.0039)
end
```
@ -87,7 +76,7 @@ You may also subscribe to events matching a regular expression. This enables you
multiple events at once. Here's how to subscribe to everything from `ActionController`:
```ruby
ActiveSupport::Notifications.subscribe(/action_controller/) do |*args|
ActiveSupport::Notifications.subscribe(/action_controller/) do |event|
# inspect all ActionController events
end
```