2 files changed, 39 insertions, 10 deletions
diff --git a/activesupport/lib/active_support/log_subscriber.rb b/activesupport/lib/active_support/log_subscriber.rb
index d5f0e3fa6c..2e423b0364 100644
--- a/activesupport/lib/active_support/log_subscriber.rb
+++ b/activesupport/lib/active_support/log_subscriber.rb
@@ -61,7 +61,7 @@ module ActiveSupport
         @@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 @@ module ActiveSupport
       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
 
diff --git a/activesupport/lib/active_support/notifications/instrumenter.rb b/activesupport/lib/active_support/notifications/instrumenter.rb
index 58e292c658..7dfea4bb4b 100644
--- a/activesupport/lib/active_support/notifications/instrumenter.rb
+++ b/activesupport/lib/active_support/notifications/instrumenter.rb
@@ -31,7 +31,8 @@ module ActiveSupport
     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
@@ -39,12 +40,19 @@ module ActiveSupport
         @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