diff options
| -rw-r--r-- | activesupport/CHANGELOG.md | 4 | ||||
| -rw-r--r-- | activesupport/lib/active_support/notifications/instrumenter.rb | 47 | ||||
| -rw-r--r-- | activesupport/lib/active_support/subscriber.rb | 7 | ||||
| -rw-r--r-- | activesupport/test/log_subscriber_test.rb | 11 |
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" |