make events not use date and time to determine parent_of. fixes rails#5932

Author: takoyakikamen

activesupport/lib/active_support/log_subscriber.rb

@@ -61,7 +61,7 @@ def attach_to(namespace, log_subscriber=new, notifier=ActiveSupport::Notificatio
         @@flushable_loggers = nil
 
         log_subscriber.public_methods(false).each do |event|
-          next if :call == event
+          next if %w{ start finish }.include?(event.to_s)
 
           notifier.subscribe("#{event}.#{namespace}", log_subscriber)
         end
@@ -86,14 +86,35 @@ def flush_all!
       end
     end
 
-    def call(message, *args)
+    def initialize
+      @event_stack = Hash.new { |h,id|
+        h[id] = Hash.new { |ids,name| ids[name] = [] }
+      }
+      super
+    end
+
+    def start(name, id, payload)
+      return unless logger
+
+      e = ActiveSupport::Notifications::Event.new(name, Time.now, nil, id, payload)
+      parent = @event_stack[id][name].last
+      parent << e if parent
+
+      @event_stack[id][name].push e
+    end
+
+    def finish(name, id, payload)
       return unless logger
 
-      method = message.split('.').first
+      finished  = Time.now
+      event     = @event_stack[id][name].pop
+      event.end = finished
+
+      method = name.split('.').first
       begin
-        send(method, ActiveSupport::Notifications::Event.new(message, *args))
-      rescue => e
-        logger.error "Could not log #{message.inspect} event. #{e.class}: #{e.message} #{e.backtrace}"
+        send(method, event)
+      rescue Exception => e
+        logger.error "Could not log #{name.inspect} event. #{e.class}: #{e.message} #{e.backtrace}"
       end
     end
 

activesupport/lib/active_support/notifications/instrumenter.rb

@@ -31,20 +31,28 @@ def unique_id
     end
 
     class Event
-      attr_reader :name, :time, :end, :transaction_id, :payload, :duration
+      attr_reader :name, :time, :transaction_id, :payload, :children
+      attr_accessor :end
 
       def initialize(name, start, ending, transaction_id, payload)
         @name           = name
         @payload        = payload.dup
         @time           = start
         @transaction_id = transaction_id
         @end            = ending
-        @duration       = 1000.0 * (@end - @time)
+        @children       = []
+      end
+
+      def duration
+        1000.0 * (self.end - time)
+      end
+
+      def <<(event)
+        @children << event
       end
 
       def parent_of?(event)
-        start = (time - event.time) * 1000
-        start <= 0 && (start + duration >= event.duration)
+        @children.include? event
       end
     end
   end

activesupport/test/notifications_test.rb

@@ -221,13 +221,15 @@ def test_events_consumes_information_given_as_payload
       assert_equal Hash[:payload => :bar], event.payload
     end
 
-    def test_event_is_parent_based_on_time_frame
+    def test_event_is_parent_based_on_children
       time = Time.utc(2009, 01, 01, 0, 0, 1)
 
       parent    = event(:foo, Time.utc(2009), Time.utc(2009) + 100, random_id, {})
       child     = event(:foo, time, time + 10, random_id, {})
       not_child = event(:foo, time, time + 100, random_id, {})
 
+      parent.children << child
+
       assert parent.parent_of?(child)
       assert !child.parent_of?(parent)
       assert !parent.parent_of?(not_child)