diff options
| -rw-r--r-- | activesupport/lib/active_support/notifications.rb | 35 | ||||
| -rw-r--r-- | activesupport/lib/active_support/notifications/fanout.rb | 25 | ||||
| -rw-r--r-- | activesupport/test/notifications_test.rb | 69 | ||||
| -rw-r--r-- | guides/source/active_support_instrumentation.md | 11 |
4 files changed, 131 insertions, 9 deletions
diff --git a/activesupport/lib/active_support/notifications.rb b/activesupport/lib/active_support/notifications.rb index d9e93b530c..555c0ad1d3 100644 --- a/activesupport/lib/active_support/notifications.rb +++ b/activesupport/lib/active_support/notifications.rb @@ -38,6 +38,19 @@ module ActiveSupport # payload # => Hash, the payload # end # + # Here, the +start+ and +finish+ values represent wall-clock time. If you are + # concerned about accuracy, you can register a monotonic subscriber. + # + # 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 + # 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 = [] @@ -135,6 +148,16 @@ module ActiveSupport # during the execution of the block. The callback is unsubscribed automatically # after that. # + # To record +started+ and +finished+ values with monotonic time, + # specify the optional <tt>:monotonic</tt> option to the + # <tt>subscribed</tt> method. The <tt>:monotonic</tt> option is set + # to +false+ by default. + # + # callback = lambda {|name, started, finished, unique_id, payload| ... } + # ActiveSupport::Notifications.subscribed(callback, "sql.active_record", monotonic: true) do + # ... + # end + # # === Manual Unsubscription # # The +subscribe+ method returns a subscriber object: @@ -209,11 +232,17 @@ module ActiveSupport # @event = event # end def subscribe(*args, &block) - notifier.subscribe(*args, &block) + pattern, callback = *args + notifier.subscribe(pattern, callback, false, &block) + end + + def monotonic_subscribe(*args, &block) + pattern, callback = *args + notifier.subscribe(pattern, callback, true, &block) end - def subscribed(callback, *args, &block) - subscriber = subscribe(*args, &callback) + def subscribed(callback, pattern, monotonic: false, &block) + subscriber = notifier.subscribe(pattern, callback, monotonic) yield ensure unsubscribe(subscriber) diff --git a/activesupport/lib/active_support/notifications/fanout.rb b/activesupport/lib/active_support/notifications/fanout.rb index c506b35b1e..c37bec4ee5 100644 --- a/activesupport/lib/active_support/notifications/fanout.rb +++ b/activesupport/lib/active_support/notifications/fanout.rb @@ -20,8 +20,8 @@ module ActiveSupport super end - def subscribe(pattern = nil, callable = nil, &block) - subscriber = Subscribers.new(pattern, callable || block) + def subscribe(pattern = nil, callable = nil, monotonic = false, &block) + subscriber = Subscribers.new(monotonic, pattern, callable || block) synchronize do if String === pattern @string_subscribers[pattern] << subscriber @@ -84,8 +84,8 @@ module ActiveSupport end module Subscribers # :nodoc: - def self.new(pattern, listener) - subscriber_class = Timed + def self.new(monotonic, pattern, listener) + subscriber_class = monotonic ? MonotonicTimed : Timed if listener.respond_to?(:start) && listener.respond_to?(:finish) subscriber_class = Evented @@ -190,6 +190,23 @@ module ActiveSupport end end + class MonotonicTimed < Evented # :nodoc: + def publish(name, *args) + @delegate.call name, *args + end + + def start(name, id, payload) + timestack = Thread.current[:_timestack_monotonic] ||= [] + timestack.push Concurrent.monotonic_time + end + + def finish(name, id, payload) + timestack = Thread.current[:_timestack_monotonic] + started = timestack.pop + @delegate.call(name, started, Concurrent.monotonic_time, id, payload) + end + end + class EventObject < Evented def start(name, id, payload) stack = Thread.current[:_event_stack] ||= [] diff --git a/activesupport/test/notifications_test.rb b/activesupport/test/notifications_test.rb index d3c660a014..3b98749f1b 100644 --- a/activesupport/test/notifications_test.rb +++ b/activesupport/test/notifications_test.rb @@ -62,6 +62,38 @@ module Notifications end end + class TimedAndMonotonicTimedSubscriberTest < TestCase + def test_subscribe + event_name = "foo" + class_of_started = nil + class_of_finished = nil + + ActiveSupport::Notifications.subscribe(event_name) do |name, started, finished, unique_id, data| + class_of_started = started.class + class_of_finished = finished.class + end + + ActiveSupport::Notifications.instrument(event_name) + + assert_equal [Time, Time], [class_of_started, class_of_finished] + end + + def test_monotonic_subscribe + event_name = "foo" + class_of_started = nil + class_of_finished = nil + + ActiveSupport::Notifications.monotonic_subscribe(event_name) do |name, started, finished, unique_id, data| + class_of_started = started.class + class_of_finished = finished.class + end + + ActiveSupport::Notifications.instrument(event_name) + + assert_equal [Float, Float], [class_of_started, class_of_finished] + end + end + class SubscribedTest < TestCase def test_subscribed name = "foo" @@ -95,6 +127,42 @@ module Notifications ensure ActiveSupport::Notifications.notifier = old_notifier end + + def test_timed_subscribed + event_name = "foo" + class_of_started = nil + class_of_finished = nil + callback = lambda do |name, started, finished, unique_id, data| + class_of_started = started.class + class_of_finished = finished.class + end + + ActiveSupport::Notifications.subscribed(callback, event_name) do + ActiveSupport::Notifications.instrument(event_name) + end + + ActiveSupport::Notifications.instrument(event_name) + + assert_equal [Time, Time], [class_of_started, class_of_finished] + end + + def test_monotonic_timed_subscribed + event_name = "foo" + class_of_started = nil + class_of_finished = nil + callback = lambda do |name, started, finished, unique_id, data| + class_of_started = started.class + class_of_finished = finished.class + end + + ActiveSupport::Notifications.subscribed(callback, event_name, monotonic: true) do + ActiveSupport::Notifications.instrument(event_name) + end + + ActiveSupport::Notifications.instrument(event_name) + + assert_equal [Float, Float], [class_of_started, class_of_finished] + end end class UnsubscribeTest < TestCase @@ -317,7 +385,6 @@ module Notifications assert_equal 0, event.cpu_time end - def test_events_consumes_information_given_as_payload event = event(:foo, Concurrent.monotonic_time, Concurrent.monotonic_time + 1, random_id, payload: :bar) assert_equal Hash[payload: :bar], event.payload diff --git a/guides/source/active_support_instrumentation.md b/guides/source/active_support_instrumentation.md index 4868b00bbe..9f15e70da6 100644 --- a/guides/source/active_support_instrumentation.md +++ b/guides/source/active_support_instrumentation.md @@ -643,7 +643,16 @@ The block receives the following arguments: ```ruby ActiveSupport::Notifications.subscribe "process_action.action_controller" do |name, started, finished, unique_id, data| # your own custom stuff - Rails.logger.info "#{name} Received!" + 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| + # 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 ``` |