Add cpu_time, idle_time, and allocations to Event

* Use process clock instead of Time.now

This fixes any issues with the system clock changing and also eliminates
2 object allocations per event.

* Add start! and finish! methods to the event object so we can record
more information

* Adds cpu time, idle time, and allocation count for a particular event.

Co-authored-by: Aaron Patterson <aaron.patterson@gmail.com>

activesupport/CHANGELOG.md

@@ -1,3 +1,7 @@
+*   Add cpu_time, idle_time, and allocations to Event
+
+    *Eileen M. Uchitelle*, *Aaron Patterson*
+
 *   RedisCacheStore: support key expiry in increment/decrement.
 
     Pass `:expires_in` to `#increment` and `#decrement` to set a Redis EXPIRE on the key.

activesupport/lib/active_support/notifications/instrumenter.rb

@@ -63,6 +63,34 @@ module ActiveSupport
         @end            = ending
         @children       = []
         @duration       = nil
+        @cpu_time_start = nil
+        @cpu_time_finish = nil
+        @allocation_count_start = 0
+        @allocation_count_finish = 0
+      end
+
+      def start!
+        @time = now
+        @cpu_time_start = now_cpu
+        @allocation_count_start = now_allocations
+      end
+
+      def finish!
+        @end = now
+        @cpu_time_finish = now_cpu
+        @allocation_count_finish = now_allocations
+      end
+
+      def cpu_time
+        @cpu_time_finish - @cpu_time_start
+      end
+
+      def idle_time
+        duration - cpu_time
+      end
+
+      def allocations
+        @allocation_count_finish - @allocation_count_start
       end
 
       # Returns the difference in milliseconds between when the execution of the
@@ -88,6 +116,25 @@ module ActiveSupport
       def parent_of?(event)
         @children.include? event
       end
+
+      private
+        def now
+          Process.clock_gettime(Process::CLOCK_MONOTONIC)
+        end
+
+        def now_cpu
+          Process.clock_gettime(Process::CLOCK_PROCESS_CPUTIME_ID)
+        end
+
+        if defined?(JRUBY_VERSION)
+          def now_allocations
+            0
+          end
+        else
+          def now_allocations
+            GC.stat :total_allocated_objects
+          end
+        end
     end
   end
 end

activesupport/lib/active_support/subscriber.rb

@@ -79,7 +79,8 @@ module ActiveSupport
     end
 
     def start(name, id, payload)
-      e = ActiveSupport::Notifications::Event.new(name, Time.now, nil, id, payload)
+      e = ActiveSupport::Notifications::Event.new(name, nil, nil, id, payload)
+      e.start!
       parent = event_stack.last
       parent << e if parent
 
@@ -87,9 +88,8 @@ module ActiveSupport
     end
 
     def finish(name, id, payload)
-      finished  = Time.now
       event     = event_stack.pop
-      event.end = finished
+      event.finish!
       event.payload.merge!(payload)
 
       method = name.split(".".freeze).first
@@ -97,7 +97,6 @@ module ActiveSupport
     end
 
     private
-
       def event_stack
         SubscriberQueueRegistry.instance.get_queue(@queue_key)
       end

activesupport/test/log_subscriber_test.rb

@@ -75,6 +75,17 @@ class SyncLogSubscriberTest < ActiveSupport::TestCase
     assert_kind_of ActiveSupport::Notifications::Event, @log_subscriber.event
   end
 
+  def test_event_attributes
+    ActiveSupport::LogSubscriber.attach_to :my_log_subscriber, @log_subscriber
+    instrument "some_event.my_log_subscriber"
+    wait
+    event = @log_subscriber.event
+    assert_operator event.duration, :>, 0
+    assert_operator event.cpu_time, :>, 0
+    assert_operator event.idle_time, :>, 0
+    assert_operator event.allocations, :>, 0
+  end
+
   def test_does_not_send_the_event_if_it_doesnt_match_the_class
     ActiveSupport::LogSubscriber.attach_to :my_log_subscriber, @log_subscriber
     instrument "unknown_event.my_log_subscriber"