Introduce 'ActiveSupport::Notifications::Fanout::Subscribers::MonotonicTimed' and 'ActiveSupport::Notifications::monotonic_subscribe'

vishaltelangre · vishaltelangre · commit 93b652affbed · 2019-05-10T20:16:17.000+05:30
Also, change the signature of ‘ActiveSupport::Notifications::Fanout#subscribe’ to accept optional ‘monotonic’ boolean argument. Then initialize either a ‘Timed’ or ‘MonotonicTimed’ subscriber based on the value of ‘monotonic’ parameter.

Introduce ‘ActiveSupport::Notifications::monotonic_subscribe’ method

Also, provision ‘ActiveSupport::Notifications::subscribed’ to optionally accept ‘monotonic’ boolean argument.

Update documentation for ActiveSupport::Notifications

Add tests

Update guides documentation under the 'Active Support Instrumentation' chapter

Incorporate feedback: use optional keyword argument to specify optional 'monotonic' option to 'subscribed' method

Fix a typo
diff --git 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 @@ def instrument(name, payload = {})
       #     @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
@@ -20,8 +20,8 @@ def initialize
         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 @@ def wait
       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 @@ def finish(name, id, payload)
           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
@@ -62,6 +62,38 @@ def test_subscribe_via_top_level_api
     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 @@ def test_subscribing_to_instrumentation_while_inside_it
     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 @@ def test_event_cpu_time_does_not_raise_error_when_start_or_finished_not_called
       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
@@ -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
 ```
 
