--- title: "Rails 6 improves ActiveSupport::Notifications::Event" description: "Rails 6 adds CPU time, idle time and allocations to ActiveSupport::Notifications::Event" canonical_url: "https://www.bigbinary.com/blog/rails-6-adds-cpu-time-idle-time-and-allocations-to-activesupport-notifications-event" markdown_url: "https://www.bigbinary.com/blog/rails-6-adds-cpu-time-idle-time-and-allocations-to-activesupport-notifications-event.md" --- # Rails 6 improves ActiveSupport::Notifications::Event Rails 6 adds CPU time, idle time and allocations to ActiveSupport::Notifications::Event - Author: Vishal Telangre - Published: April 24, 2019 - Categories: Rails 6, Rails Rails provides an easy way to instrument events and ability to subscribe to those events using [Active Support Instrumentation](https://guides.rubyonrails.org/active_support_instrumentation.html) API. ## Before Rails 6 Before Rails 6, the subscriber of an event can access the event's start time, end time and the duration along with the other event information. To demonstrate how to access this information from an event, we will instrument a custom event `custom_sleep_event` and attach a subscriber to that event. ```ruby ActiveSupport::Notifications.subscribe('custom_sleep_event') do |*args| event = ActiveSupport::Notifications::Event.new(*args) puts "Event: #{event.inspect}" puts "Started: #{event.time}" puts "Finished: #{event.end}" puts "Duration (ms): #{event.duration}" end ActiveSupport::Notifications.instrument('custom_sleep_event') do sleep 2 end ``` The event subscriber should print something similar. ```plaintext Event: # Started: 2019-04-11 16:58:52 +0530 Finished: 2019-04-11 16:58:54 +0530 Duration (ms): 2001.287 ``` ## Improvements and additions made to ActiveSupport::Notifications::Event in Rails 6 Rails 6 has improved the way an event's duration is computed and also added useful information accessible on an event object such as CPU time, idle time and allocations. Let's discuss it in more detail. ##### 1. `CLOCK_MONOTONIC` instead of `CLOCK_REALTIME` Before Rails 6, `Time.now` is used for recording the event's start time and end time. To avoid [issues with the machine changing time](https://github.com/rails/rails/issues/34271), Rails 6 now uses [`Concurrent.monotonic_time`](https://www.rubydoc.info/gems/concurrent-ruby/Concurrent.monotonic_time) instead of `Time.now` to record the event's both start time and end time accurately. Initially [`Process.clock_gettime(Process::CLOCK_MONOTONIC)`](https://ruby-doc.org/core-2.5.3/Process.html#method-c-clock_gettime) was used which [later modified](https://github.com/rails/rails/commit/dda9452314bb904a3e2c850bd23f118eb80e3356#diff-b82336d1f77b84d28210f9b46fcff97d) to use `Concurrent.monotonic_time`. Note that `Concurrent.monotonic_time` is same but returns more precise time than `Process.clock_gettime(Process::CLOCK_MONOTONIC)`. > `Time.now` or `Process.clock_gettime(Process::CLOCK_REALTIME)` can jump > forwards and backwards as the system time-of-day clock is changed. Whereas, > clock time using `CLOCK_MONOTONIC` returns the absolute wall-clock time since > an unspecified time in the past (for example, system start-up time, or the > Epoch). The `CLOCK_MONOTONIC` does not change with the system time-of-day > clock, it just keeps advances forwards at one tick per tick and resets if the > system is rebooted. In general, `CLOCK_MONOTONIC` is recommended to compute > the elapsed time between two events. To read more about the differences > between `CLOCK_REALTIME` and `CLOCK_MONOTONIC`, please check the discussion on > [this Stackoverflow thread](https://stackoverflow.com/questions/3523442/> > difference-between-clock-realtime-and-clock-monotonic). Another > [article](https://blog.dnsimple.com/2018/03/elapsed-time-with-ruby-the-right-way/) > written by Luca Guidi on the same topic is a recommended read. ##### 2. No need to create hand made event objects on our own Since it is a common practice to initialize an event using `ActiveSupport::Notifications::Event.new(*args)` in the event subscriber block, [Rails 6 now makes this a bit easy](https://github.com/rails/rails/pull/33451). If the block passed to the subscriber only takes one argument then the Active Support Notification framework now yields an event object to the block. Therefore, the subscriber definition below ```ruby ActiveSupport::Notifications.subscribe('an_event') do |*args| event = ActiveSupport::Notifications::Event.new(*args) puts "Event #{event.name} received." end ``` now can be simplified in Rails 6 as follows. ```ruby ActiveSupport::Notifications.subscribe('an_event') do |event| puts "Event #{event.name} received." end ``` ##### 3. CPU time and idle time Rails 6 now computes elapsed CPU time of an event with the help of [`Process.clock_gettime(Process::CLOCK_PROCESS_CPUTIME_ID)`](https://ruby-doc.org/core-2.5.3/Process.html#method-c-clock_gettime). System (kernel) keeps track of CPU time per process. The clock time returned using `CLOCK_PROCESS_CPUTIME_ID` represents the CPU time that has passed since the process started. Since a process may not always get all CPU cycles between start and finish of the process, the process often has to (sleep and) share CPU time among other processes. If the system puts a process to sleep, then the time spend waiting is not counted in the process' CPU time. The CPU time of an event can be fetched using the `#cpu_time` method. Also, Rails 6 now computes the idle time of an event, too. The idle time of an event represents the difference between the event's `#duration` and `#cpu_time`. Note that the `#duration` is computed using the difference between the event's monotonic time at the start (`#time`) and the monotonic time at the end (`#end`). Let's see how to get these time values. ```ruby ActiveSupport::Notifications.subscribe('custom_sleep_event') do |event| puts "Event: #{event.inspect}" puts "Started: #{event.time}" puts "Finished: #{event.end}" puts "Duration (ms): #{event.duration}" puts "CPU time (ms): #{event.cpu_time}" puts "Idle time (ms): #{event.idle_time}" end ActiveSupport::Notifications.instrument('custom_sleep_event') do sleep 2 end ``` It prints this. ```plaintext Event: # Started: 29514.525707 Finished: 29516.528971 Duration (ms): 2003.2639999990351 CPU time (ms): 0.07299999999998974 Idle time (ms): 2003.190999999035 ``` Notice the `@cpu_time_start` and `@cpu_time_finish` counters in the inspected event object representation which are used to calculate the CPU time. ##### 4. Allocations We will now know how many objects were allocated between the start and end of an event using event's `#allocations` method. ```ruby ActiveSupport::Notifications.subscribe('custom_sleep_event') do |event| puts "Event: #{event.inspect}" puts "Started: #{event.time}" puts "Finished: #{event.end}" puts "Duration (ms): #{event.duration}" puts "CPU time (ms): #{event.cpu_time}" puts "Idle time (ms): #{event.idle_time}" puts "# of objects allocated: #{event.allocations}" end ActiveSupport::Notifications.instrument('custom_sleep_event') do sleep 2 end ``` The above example should print something like this. ```plaintext Event: # Started: 30503.508897 Finished: 30505.513547 Duration (ms): 2004.6499999989464 CPU time (ms): 0.17299999999975668 Idle time (ms): 2004.4769999989467 # of objects allocated: 1 ``` Notice the `@allocation_count_finish` and `@allocation_count_start` counters in the inspected event object representation which are used to calculate the number of objects allocated during an event whose difference is (834228 - 834227 = 1). > In case of JRuby, the > [allocations would be zero](https://github.com/rails/rails/blob/3e628c48406440811f9201e2db7ba0df53bb38e1/activesupport/lib/active_support/notifications/instrumenter.rb#L155-L157). ##### 5. `#start!` and `#finish!` Two public methods `#start!` and `#finish!` have been introduced to `ActiveSupport::Notifications::Event` which can be used to record more information. The `#start!` method [resets](https://github.com/rails/rails/blob/45511fa8b20c621e2cf193ddaeb7d6fbe8432fea/activesupport/lib/active_support/notifications/instrumenter.rb#L79-L83) the `@time`, `@cpu_time_start` and `@allocation_count_start` counters. Similarly, the `#finish!` method also [resets](https://github.com/rails/rails/blob/45511fa8b20c621e2cf193ddaeb7d6fbe8432fea/activesupport/lib/active_support/notifications/instrumenter.rb#L86-L90) the `@end`, `@cpu_time_finish` and `@allocation_count_finish` counters. --- To learn more about this feature, please check [rails/rails#33449](https://github.com/rails/rails/pull/33449). ## Links - [Human page](https://www.bigbinary.com/blog/rails-6-adds-cpu-time-idle-time-and-allocations-to-activesupport-notifications-event)