Rails 6 improves ActiveSupport::Notifications::Event

Rails provides an easy way to instrument events and ability to subscribe to those events using Active Support Instrumentation 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.

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.

Event: #<ActiveSupport::Notifications::Event:0x00007f952fc6a0b8 @name="custom_sleep_event", @payload={}, @time=2019-04-11 16:58:52 +0530, @transaction_id="e82231ab65b7af3c85ec", @end=2019-04-11 16:58:54 +0530, @children=[], @duration=nil>

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, Rails 6 now uses 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) was used which later modified 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 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. 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

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.

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).

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.

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.

Event: #<ActiveSupport::Notifications::Event:0x00007fb02ac72400 @name="custom_sleep_event", @payload={}, @time=29514.525707, @transaction_id="43ca8e1c378b6b00d861", @end=29516.528971, @children=[], @duration=nil, @cpu_time_start=2.238801, @cpu_time_finish=2.238874, @allocation_count_start=835821, @allocation_count_finish=835821>

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.

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.

Event: #<ActiveSupport::Notifications::Event:0x00007fed8c4e33c0 @name="custom_sleep_event", @payload={}, @time=30503.508897, @transaction_id="5330165dae2b49fbe143", @end=30505.513547, @children=[], @duration=nil, @cpu_time_start=2.813231, @cpu_time_finish=2.813404, @allocation_count_start=834227, @allocation_count_finish=834228>

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.

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 the @time, @cpu_time_start and @allocation_count_start counters. Similarly, the #finish! method also resets the @end, @cpu_time_finish and @allocation_count_finish counters.

To learn more about this feature, please check rails/rails#33449.