We write about Ruby on Rails, React.js, React Native, remote work, open source, engineering and design.
Rails 6.0 was recently released.
Rails provides an easy way to instrument events and ability to subscribe to those events using Active Support Instrumentation API.
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.
1ActiveSupport::Notifications.subscribe('custom_sleep_event') do |*args|
2 event = ActiveSupport::Notifications::Event.new(*args)
3
4 puts "Event: #{event.inspect}"
5 puts "Started: #{event.time}"
6 puts "Finished: #{event.end}"
7 puts "Duration (ms): #{event.duration}"
8end
9
10ActiveSupport::Notifications.instrument('custom_sleep_event') do
11 sleep 2
12end
The event subscriber should print something similar.
1Event: #<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>
2
3Started: 2019-04-11 16:58:52 +0530
4
5Finished: 2019-04-11 16:58:54 +0530
6
7Duration (ms): 2001.287
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.
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
orProcess.clock_gettime(Process::CLOCK_REALTIME)
can jump forwards and backwards as the system time-of-day clock is changed. Whereas, clock time usingCLOCK_MONOTONIC
returns the absolute wall-clock time since an unspecified time in the past (for example, system start-up time, or the Epoch). TheCLOCK_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 betweenCLOCK_REALTIME
andCLOCK_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.
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
1ActiveSupport::Notifications.subscribe('an_event') do |*args|
2 event = ActiveSupport::Notifications::Event.new(*args)
3
4 puts "Event #{event.name} received."
5end
now can be simplified in Rails 6 as follows.
1ActiveSupport::Notifications.subscribe('an_event') do |event|
2 puts "Event #{event.name} received."
3end
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.
1ActiveSupport::Notifications.subscribe('custom_sleep_event') do |event|
2 puts "Event: #{event.inspect}"
3 puts "Started: #{event.time}"
4 puts "Finished: #{event.end}"
5 puts "Duration (ms): #{event.duration}"
6 puts "CPU time (ms): #{event.cpu_time}"
7 puts "Idle time (ms): #{event.idle_time}"
8end
9
10ActiveSupport::Notifications.instrument('custom_sleep_event') do
11 sleep 2
12end
It prints this.
1Event: #<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>
2
3Started: 29514.525707
4
5Finished: 29516.528971
6
7Duration (ms): 2003.2639999990351
8
9CPU time (ms): 0.07299999999998974
10
11Idle 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.
We will now know how many objects were allocated
between the start and end of an event
using event's #allocations
method.
1ActiveSupport::Notifications.subscribe('custom_sleep_event') do |event|
2 puts "Event: #{event.inspect}"
3 puts "Started: #{event.time}"
4 puts "Finished: #{event.end}"
5 puts "Duration (ms): #{event.duration}"
6 puts "CPU time (ms): #{event.cpu_time}"
7 puts "Idle time (ms): #{event.idle_time}"
8 puts "# of objects allocated: #{event.allocations}"
9end
10
11ActiveSupport::Notifications.instrument('custom_sleep_event') do
12 sleep 2
13end
The above example should print something like this.
1Event: #<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>
2
3Started: 30503.508897
4
5Finished: 30505.513547
6
7Duration (ms): 2004.6499999989464
8
9CPU time (ms): 0.17299999999975668
10
11Idle time (ms): 2004.4769999989467
12
13# 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.
#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.