Merge pull request #33449 from rails/use-process-clock-instead-of-time

Add cpu time, idle time, and allocations features to log subscriber events

4 files changed, 65 insertions, 4 deletions

diff --git a/activesupport/CHANGELOG.md b/activesupport/CHANGELOG.md
index 24ad72c45d..10a25a120d 100644
--- a/activesupport/CHANGELOG.md
+++ b/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.
diff --git a/activesupport/lib/active_support/notifications/instrumenter.rb b/activesupport/lib/active_support/notifications/instrumenter.rb
index e99f5ee688..ddcd1661e4 100644
--- a/activesupport/lib/active_support/notifications/instrumenter.rb
+++ b/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
diff --git a/activesupport/lib/active_support/subscriber.rb b/activesupport/lib/active_support/subscriber.rb
index 8ad39f7a05..54c770ac35 100644
--- a/activesupport/lib/active_support/subscriber.rb
+++ b/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
diff --git a/activesupport/test/log_subscriber_test.rb b/activesupport/test/log_subscriber_test.rb
index 2af9b1de30..4f413b9627 100644
--- a/activesupport/test/log_subscriber_test.rb
+++ b/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"