aboutsummaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
-rw-r--r--activesupport/CHANGELOG.md4
-rw-r--r--activesupport/lib/active_support/notifications/instrumenter.rb47
-rw-r--r--activesupport/lib/active_support/subscriber.rb7
-rw-r--r--activesupport/test/log_subscriber_test.rb11
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"