Merge pull request rails#50779 from Shopify/debug-ar-time

Fix `ActiveSupport::Notifications.publish_event` to preserve units

Author: byroot

activesupport/lib/active_support/notifications/instrumenter.rb

@@ -104,7 +104,7 @@ def unique_id
     end
 
     class Event
-      attr_reader :name, :time, :end, :transaction_id
+      attr_reader :name, :transaction_id
       attr_accessor :payload
 
       def initialize(name, start, ending, transaction_id, payload)
@@ -119,7 +119,15 @@ def initialize(name, start, ending, transaction_id, payload)
         @allocation_count_finish = 0
       end
 
-      def record
+      def time
+        @time / 1000.0 if @time
+      end
+
+      def end
+        @end / 1000.0 if @end
+      end
+
+      def record # :nodoc:
         start!
         begin
           yield payload if block_given?
@@ -195,7 +203,7 @@ def parent_of?(event) # :nodoc:
       #
       #   @event.duration # => 1000.138
       def duration
-        self.end - time
+        @end - @time
       end
 
       private

activesupport/test/subscriber_test.rb

@@ -127,4 +127,25 @@ def test_supports_publish_event
   ensure
     TestSubscriber.detach_from :doodle
   end
+
+  def test_publish_event_preserve_units
+    event = ActiveSupport::Notifications::Event.new("publish_event.test", nil, nil, 42, {})
+    event.record { sleep 0.1 }
+
+    computed_duration = nil
+    callback = -> (_, start, finish, _, _) { computed_duration = finish - start }
+
+    ActiveSupport::Notifications.subscribed(callback, "publish_event.test") do
+      ActiveSupport::Notifications.publish_event(event)
+    end
+
+    # Event#duration is in milliseconds, start and finish in seconds
+    assert_in_delta event.duration / 1_000.0, computed_duration, 0.05
+
+    ActiveSupport::Notifications.subscribed(callback, "publish_event.test", monotonic: true) do
+      ActiveSupport::Notifications.publish_event(event)
+    end
+
+    assert_in_delta event.duration / 1_000.0, computed_duration, 0.05
+  end
 end