Optimize AS::LogSubscriber

[casperisfine]

The various LogSubscriber subclasses tend to subscribe to events but then end up doing nothing if the log level is high enough.

But even if we end up not logging, we have to go through the entire notification path, record timing etc.

By allowing subscribers to dynamically bail out early, we can save a lot of work if all subscribers are silenced.

[jhawthorn]

This seems to hurt the benchmark from #44469 a little bit... still faster than before that PR, but measurable. Maybe due to the extra filtering?

Before:

$ be ruby benchmark_notifications.rb
Warming up --------------------------------------
               timed    26.252k i/100ms
     timed_monotonic    33.989k i/100ms
        event_object    23.774k i/100ms
             evented    30.815k i/100ms
        unsubscribed   383.906k i/100ms
Calculating -------------------------------------
               timed    266.360k (± 0.2%) i/s -      1.339M in   5.026492s
     timed_monotonic    339.195k (± 0.3%) i/s -      1.699M in   5.010288s
        event_object    236.727k (± 0.6%) i/s -      1.189M in   5.021568s
             evented    308.301k (± 0.2%) i/s -      1.572M in   5.097533s
        unsubscribed      3.838M (± 0.4%) i/s -     19.195M in   5.002079s

After:

$ be ruby benchmark_notifications.rb
Warming up --------------------------------------
               timed    17.996k i/100ms
     timed_monotonic    20.696k i/100ms
        event_object    16.694k i/100ms
             evented    19.664k i/100ms
        unsubscribed   326.481k i/100ms
Calculating -------------------------------------
               timed    178.232k (± 0.4%) i/s -    899.800k in   5.048546s
     timed_monotonic    206.379k (± 0.4%) i/s -      1.035M in   5.014147s
        event_object    167.198k (± 0.3%) i/s -    851.394k in   5.092191s
             evented    197.051k (± 0.2%) i/s -      1.003M in   5.089377s
        unsubscribed      3.284M (± 0.3%) i/s -     16.651M in   5.069612s

[jhawthorn]

One option might be creating a new group_klass for these silencable? subscribers. They're all the same type, so it should just be one more type of group, that way we'd only pay this extra cost for the actually silencable topics and subscribers.

[casperisfine]

Thanks for pointing out you benchmark. I managed to get back to only ~5% slower.

Not sure we can do much better as ultimately not being able to cache the whole thing necessarily is a bit more work.

However my assumption here is that some frequent events are only subscribed by various LogSubscribers that end up being noops in most case. If that assumption holds up, then we're way way faster. However if they are indeed subscribed in prod, then we'd take the 5% hit.

results

=== timed ===
Warming up --------------------------------------
log-subscriber-silenced
                        34.802k i/100ms
Calculating -------------------------------------
log-subscriber-silenced
                        347.120k (± 0.5%) i/s -      1.740M in   5.013076s

Comparison:
                main:   363889.2 i/s
log-subscriber-silenced:   347119.9 i/s - 1.05x  (± 0.00) slower


=== timed_monotonic ===
Warming up --------------------------------------
log-subscriber-silenced
                        42.030k i/100ms
Calculating -------------------------------------
log-subscriber-silenced
                        420.788k (± 0.4%) i/s -      2.144M in   5.094174s

Comparison:
                main:   447503.6 i/s
log-subscriber-silenced:   420787.8 i/s - 1.06x  (± 0.00) slower


=== event_object ===
Warming up --------------------------------------
log-subscriber-silenced
                        31.650k i/100ms
Calculating -------------------------------------
log-subscriber-silenced
                        316.084k (± 0.6%) i/s -      1.582M in   5.006794s

Comparison:
                main:   329884.8 i/s
log-subscriber-silenced:   316083.7 i/s - 1.04x  (± 0.00) slower


=== evented ===
Warming up --------------------------------------
log-subscriber-silenced
                        37.191k i/100ms
Calculating -------------------------------------
log-subscriber-silenced
                        372.250k (± 0.4%) i/s -      1.897M in   5.095432s

Comparison:
                main:   387598.9 i/s
log-subscriber-silenced:   372250.5 i/s - 1.04x  (± 0.00) slower


=== unsubscribed ===
Warming up --------------------------------------
log-subscriber-silenced
                       405.990k i/100ms
Calculating -------------------------------------
log-subscriber-silenced
                          4.069M (± 0.3%) i/s -     20.705M in   5.089025s

Comparison:
                main:  4090502.6 i/s
log-subscriber-silenced:  4068702.3 i/s - same-ish: difference falls within error


=== silenced ===
Warming up --------------------------------------
log-subscriber-silenced
                       104.296k i/100ms
Calculating -------------------------------------
log-subscriber-silenced
                          1.046M (± 0.3%) i/s -      5.319M in   5.086327s

Comparison:
log-subscriber-silenced:  1045773.3 i/s
                main:   390009.7 i/s - 2.68x  (± 0.00) slower

benchmark

```ruby # frozen_string_literal: true

require 'fileutils' require 'benchmark/ips' require 'active_support/all'

BRANCH = git rev-parse --abbrev-ref HEAD.strip SAVE_DIR = "/tmp/bench-notifications/" FileUtils.mkdir_p(SAVE_DIR)

class EventedSubscriber def start(name, id, payload); end def finish(name, id, payload); end end

class SilencedSubscriber < EventedSubscriber def silenced?(_name) true end end

10.times do ActiveSupport::Notifications.subscribe("timed") do |name, started, ended, id, payload| end

ActiveSupport::Notifications.monotonic_subscribe("timed_monotonic") do |name, started, ended, id, payload| end

ActiveSupport::Notifications.subscribe("event_object") do |event| end

ActiveSupport::Notifications.subscribe("evented", EventedSubscriber.new)

ActiveSupport::Notifications.subscribe("silenced", SilencedSubscriber.new) end

def bench(name, &block) puts "=== #{name} ===" Benchmark.ips do |x| x.report(BRANCH, &block) x.save! "/tmp/bench-notifications/#{name}" x.compare! end puts end

bench("timed") do ActiveSupport::Notifications.instrument("timed"){} end

bench("timed_monotonic") do ActiveSupport::Notifications.instrument("timed_monotonic"){} end

bench("event_object") do ActiveSupport::Notifications.instrument("event_object"){} end

bench("evented") do ActiveSupport::Notifications.instrument("evented"){} end

bench("unsubscribed") do ActiveSupport::Notifications.instrument("unsubscribed"){} end

bench("silenced") do ActiveSupport::Notifications.instrument("silenced"){} end

</benchmark>

[casperisfine]

Thanks for the review John!

One thing I realized I didn't handle is methods defined after attach_to was called, I'll need to do another pass.