It's possible since Rails 6 (3ea2857943dc294d7809930b4cc5b318b9c39577) to let the framework create Event objects, but the guides and docs weren't updated to lead with this example.
Manually instantiating an Event doesn't record CPU time and allocations, I've seen it more than once that people copy-pasting the example code get confused about these stats returning 0. The tests here show that - just like the apps I've worked on - the old pattern keeps getting copy-pasted.
We calculate idle time by subtracting two separately-obtained values,
and apparently it's possible for the CPU-time clock to tick a
millisecond ahead of the monotonic clock.
I think it's safe to ignore that potential difference in general, but
even at the extreme of CPU activity, I'm reasonably confident time
doesn't move backwards.
This commit aims to improve ActiveSupport::Notifications::Fanout. There
are three main goals here: backwards compatibility, safety, and
performance.
* Backwards compatibility
This ActiveSupport::Notifications is an old and well used interface.
Over time it has collected a lot of features and flexibility, much of
which I suspect is not used anywhere by anyone, but it is hard to know
specifics and we would at minimum need a deprecation cycle.
For this reason this aims to fully maintain compatibility. This includes
both the ability to use an alternate notification implementation instead
of Fanout, the signatures received by all types of listeners, and the
interface used on the Instrumenter and Fanout itself (including the
sometimes problematic start/finish).
* Safety
There have been issues (both recent and past) with the "timestacks"
becoming invalid, particularly when subscribing and unsubscribing within
events. This is an issue when topics are subscribed/unsubscribed to
while they are in flight.
The previous implementation would record a separate timestamp or event
object for each listener in a thread local stack. This meant that it was
essential that the listeners to start and finish were identical.
This issue is avoided by passing the listeners used to `start` the event
to `finish` (`finish_with_state` in the Instrumenter), to ensure they
are the same set in `start`/`finish`.
This commit further avoids this issue. Instead of pushing individual
times onto a stack, we now push a single object, `Handle`, onto the
stack for an event. This object holds all the subscribers (recorded at
start time) and all their associated data. This means that as long as
start/stop calls are not interleaved.
This commit also exposes `build_handle` as a public interface. This
returns the Handle object which can have start/stop called at any time
and any order safely. The one reservation I have with making this public
is that existing "evented" listeners (those receiving start/stop) may
not be ready for that (ex. if they maintain an internal thread-local
stack).
* Performance
This aims to be faster and make fewer allocations then the existing
implementation.
For time-based and event-object-based listeners, the previous
implementation created a separate object for each listener, pushing
and popping it on a thread-local stack. This is slower both because we
need to access the thread local repeatedly (hash lookups) and because
we're allocating duplicate objects.
The new implementation works by grouping similar types of listeners
together and shares either the `Event` or start/stop times between all
of them. The grouping was done so that we didn't need to allocate Events
or Times for topics which did have a listener of that type.
This implementation is significantly faster for all cases, except for
evented, which is slower.
For topics with 10 subscriptions:
*main*:
timed 66.739k (± 2.5%) i/s - 338.800k in 5.079883s
timed_monotonic 138.265k (± 0.6%) i/s - 699.261k in 5.057575s
event_object 48.650k (± 0.2%) i/s - 244.250k in 5.020614s
evented 366.559k (± 1.0%) i/s - 1.851M in 5.049727s
unsubscribed 3.696M (± 0.5%) i/s - 18.497M in 5.005335s
*This branch*:
timed 259.031k (± 0.6%) i/s - 1.302M in 5.025612s
timed_monotonic 327.439k (± 1.7%) i/s - 1.665M in 5.086815s
event_object 228.991k (± 0.3%) i/s - 1.164M in 5.083539s
evented 296.057k (± 0.3%) i/s - 1.501M in 5.070315s
unsubscribed 3.670M (± 0.3%) i/s - 18.376M in 5.007095s
Co-authored-by: John Crepezzi <john.crepezzi@gmail.com>
Co-authored-by: Theo Julienne <theojulienne@github.com>
A few classes hold a reference to this object (anything with a
subscription), causing the `inspect` or pretty print output to be
unreasonably large and slow.
This implements a simple representation for the Notifications::Fanout
object as users usually don't care about its internals.
Co-authored-by: Daniel Colson <danieljamescolson@gmail.com>
Example failure: https://buildkite.com/rails/rails/builds/82905#80d6c6ec-943d-4ba3-b360-1ef6c4aa5d89/1012-1022
The test designates the event end time as 0.01 seconds (i.e. 10
milliseconds) after the start time. It then asserts that the event
duration is 10 ± 0.0001 milliseconds. This sometimes fails due to
floating point precision errors.
This commit changes the assertion to instead check that the duration is
within 1% of the expected value.
Unless you are on a Ruby older than 2.3 (or some very old JRuby)
`Concurrent.monotonic_time` is just `Process.clock_gettime(Process::CLOCK_MONOTONIC)`.
So might as well skip the extra method call, and more importantly
it allows in many cases to pass the scale as second argument and save some
floating point multiplication.
Fixes#39976
Prior to this commit it was possible to pass a single argument block to
`ActiveSupport::Notifications.subscribe`, rather than 5 separate
arguments:
```rb
ActiveSupport::Notifications.subscribe('some_event') do |event|
puts "Reacting to #{event.name}"
end
```
But it was not possible to do the same with a lambda, since the lambda
parameter is a required (`:req`) parameter, but we were checking only
for an optional (`:opt`) parameter.
```rb
listener = ->(event) do
puts "Reacting to #{event.name}"
end
ActiveSupport::Notifications.subscribe('some_event', &listener)
```
It was also not possible to do this with a custom callable object, since
the custom callable does not respond directly to `:parameters` (although
it's `:call` method object does).
```rb
class CustomListener
def call(event)
puts "Reacting to #{event.name}"
end
end
ActiveSupport::Notifications.subscribe('some_event', CustomListener.new)
```
Prior to this commit these examples would have raised `ArgumentError:
wrong number of arguments (given 5, expected 1)`.
With this commit the single argument lambda and custom callable work
like the single argument block.
We now raise an argument error instead if something invalid is passed.
Partially accesses original class implementation from 4f2a04cc08 which used the case/when
When instrumenting a block of code like:
```ruby
ActiveSupport::Notifications.instrument("process_action.action_controller", raw_paylaod) do |payload|
payload[:view_runtime] = render_view
end
```
If we use an evented subscriber like so:
``` ruby
ActiveSupport::Notifications.subscribe("process_action.action_controller", raw_payload) do |event|
assert event.payload[:view_runtime]
end
```
The code breaks because the underlying EventObject's payload does not have the
`:view_runtime` key added during instrumentation.
This is because the `EventedObject` subscriber calls the `finish` method with the
`payload` of the event at the time it was pushed into the stack, before the
block executes, but we want to call `finish` with the `payload` after the
instrument block executes this way if the `payload` was modified during the block
we have access to it. This is consistent with the other types of subscribers
who don't have this bug.
Also, change the signature of ‘ActiveSupport::Notifications::Fanout#subscribe’ to accept optional ‘monotonic’ boolean argument. Then initialize either a ‘Timed’ or ‘MonotonicTimed’ subscriber based on the value of ‘monotonic’ parameter.
Introduce ‘ActiveSupport::Notifications::monotonic_subscribe’ method
Also, provision ‘ActiveSupport::Notifications::subscribed’ to optionally accept ‘monotonic’ boolean argument.
Update documentation for ActiveSupport::Notifications
Add tests
Update guides documentation under the 'Active Support Instrumentation' chapter
Incorporate feedback: use optional keyword argument to specify optional 'monotonic' option to 'subscribed' method
Fix a typo
The change to monotonic times causes failures for applications
where the subscribed block is expecting Time objects as described
in this issue: https://github.com/rails/rails/issues/36145
The original PR (https://github.com/rails/rails/pull/35984) was
concerned with errors on the cpu_time. Test was edited to reflect
changes to initializer using 0 values instead of nil
* Extend documentation of `ActiveSupport::Notifications.subscribe`
Add mention that a block with only one argument passed to the method
will yield an event object.
Related to #33451
* Emphasize that `SubscribeEventObjects` is a test class by adding suffix `Test`
We don't need to have a special subscribe method for objects. The
regular `subscribe` method is more expensive than a specialized method,
but `subscribe` should not be called frequently. If that turns out to
be a hotspot, we can introduce a specialized method. :)
Fanout notifier can send event objects to subscribers now. Also moved
`end` lower in the `finish!` method to guarantee that CPU time is
shorter than real time.
- Adds new key/value pair to payload when an exception is raised
e.g. `:exception_object=> #<RuntimeError: FAIL>`
- Updates relevant test
- Adds CHANGELOG entry
The issue is that on the exit from Instrumenter#instrument section,
an Evented listener will run into an error because its thread local
(Thread.current[:_timestack]) has not been set up by the #start
method (this obviously happens because the Evented listeners didn't
exist at the time, since no subscribtion to that section was made yet).
Note: support for subscribing to instrumented sections, while being
inside those instrumented sections, might be removed in the future.
Maybe fixes#21873.
* AS::Notifications#instrument should not measure anything, it is not its responsibility;
* Adding another argument to AS::Notifications#instrument API needs to be properly discussed;
