Subscribe to all ActiveSupport notifications

[lustickd]

It's annoying to set up traces 1 by 1 for each notification. Luckily activesupport takes a regex:

# use monotonic_subscribe if you're mocking time for rspec
ActiveSupport::Notifications.subscribe(/.*/) do |event| # or |name, start, finish, id, payload|
  tracer = OpenTelemetry.tracer_provider.tracer('active-support', '1.0')
  
  # get payload name if it exists
  payload_name = event.payload.fetch(:name, '')
  
  # format this however you want
  span_name = [event.name, payload_name].join(' ')
  
  tracer.in_span(span_name) do |span|
    # set custom attributes here
    span.set_attribute('allocations', event.allocations)
  end
end

Now every event gets traced, like sql.active_record, factory_bot.run_factory, etc..

OpenTelemetry::Instrumentation::ActiveSupport.subscribe will throw an error if you try to pass a regex. You can convert the regex to a string but you won't get the right event name in your logs.

[ahayworth]

Hey @lustickd - thanks for bringing this up! We originally envisioned that folks wouldn't want all of their notifications to be traced; we presumed that people would have a somewhat small list of things they knew needed tracing. Hence, we just supported string subscriptions. That said, I could easily see how you'd want to do something like /action_cable.*/ (or whatever), and we could probably support that.

If you're interested in contributing this, I've written up what a PR to do this would need to implement! I don't know if / when I or others would get around to working on this personally, but I would be quite happy to review a PR that provides the functionality. 😄

---

It would be possible to modify things here to accept a regular expression; the main problem is that we use the actual subscription name as part of the span name, as you can see here. Subscribing with a regex would make it impossible to know that name up-front like the code currently expects, so a few modifications would have to be made here and there:

• We'd need to change the initialize method of SpanSubscriber to accept / deal with potential Regexps.
• The start method here would need to calculate the span name from the name argument that ActiveSupport will give to us.
  • I think it would be wise to memoize it here, so that we only need to pay the string-manipulation tax the first time this notification is traced, rather than every time. This was discussed the first time around, in fact.
• The hardest part is modifying how we muck about with Rails internals, seen here.
  • The relevant code in Rails puts different subscriber types (String, Regexp, NilClass) into different variables; and our code currently does not (because ours only handles String).
  • We'd need to switch on the type of subscription just like Rails is doing, and modify the appropriate variables.
  • Take note that in Rails, @string_subscribers is a hash with string keys and array values, but @other_subscribers is just a single-dimensional array. You can see how Rails themselves is accessing it here, and we'd need to do similar things.
  • It's important to know that the purpose of modifying these internals is to ensure that our subscription is the first thing called for a notification that should be traced. That ensures we actually trace that entire notification like you would expect - we don't miss anything before the span starts. There are also some error-handling semantics that this guarantees on older versions of Rails, as alluded to in the original PR.
  • Rails 5 is different, of course, which is why this code switches on Rails version. Rails 5 should be easier to work with, I think. But you'd need to check that.

We'd really need tests ensuring the following, but for most of this it would be possible to copy / modify the tests that already exist.

• This works on Rails 5, 6, and 7 as expected.
• That subscriptions work as expected with String and Regexp subscriptions.
• That the span name is calculated correctly when the subscription was a Regexp initially.
• That the span finishes correctly when the notification blows up, when subscribed with a Regexp initially.

[lustickd]

Sure I'd like to make a PR when I have some free time. I'm debugging an issue right now that affects my project, the event duration is way shorter than it should be in ActiveSupport::Notifications for factory_bot. It doesn't happen in a fresh install though, I'm starting to wonder if we have some sort of parallelization gem laying around somewhere that's messing with the instrumentation.

It's essentially just this with the above logging snippet:

require 'active_support'
require 'factory_bot'
require 'rspec'

class SlowUser
  attr_accessor :name
end

FactoryBot.define do
  factory :slow_user do
    name { 'slowpoke' }
    after(:build) { sleep(2) }
  end
end


RSpec.describe User, type: :model do
  ActiveSupport::Notifications.instrument('slow user spec') do
    it 'logs 2 seconds in ActiveSupport' do
      slow_user = FactoryBot.build(:slow_user)
      expect(slow_user.name).to eq('slowpoke')
    end
  end
end

But it only logs 20ms instead of 2s for event duration.

Regardless, that's the sort of thing I'm trying to find out by logging all Notifications. Need to investigate file IO speeds after this, I was wondering if maybe active_support needs to be loaded REALLY early in the ruby lifecycle to get access to some of these measurements, or if ruby has something builtin for that. It wouldn't be impossible to auto-instrument your whole codebase automatically during boot for bottlenecks in file IO, networking, object allocation, memory usage, and stuff like that I think.

[lustickd]

After much investigation I've realized that my logs simply aren't making it into jaeger for factory_bot.run_factory.

# config/boot.rb
ENV['OTEL_TRACES_SAMPLER'] = 'always_on'
ENV['OTEL_TRACES_EXPORTER'] = 'jaeger'

require 'bundler/setup'
require 'active_support'
require 'opentelemetry/sdk'
require 'opentelemetry/exporter/jaeger'

OpenTelemetry::SDK.configure do |c|
  c.service_name = 'boot'
end

ActiveSupport::Notifications.subscribe(/.*/) do |event|
  tracer = OpenTelemetry.tracer_provider.tracer('active-support')
  attributes = {
    'allocactions' => event.allocations,
    'duration' => event.duration
  }
  if event.name == 'factory_bot.run_factory'
    attributes['factory_name'] = event.payload[:name].to_s
    attributes['strategy'] = event.payload[:strategy].to_s
  end

  # this isn't sending `factory_bot.run_factory` to jaeger all the time
  tracer.in_span(event.name, attributes: attributes) {}

  # console log works fine.
  if event.duration > 1000
    puts '*' * 20
    puts 'slow event: ' + event.name
    puts '  duration: ' + event.duration.to_s
    puts '*' * 20
  end
end

When I change OTEL_TRACES_EXPORTER=console I can see the trace. The weird thing is I do see some ActiveSupport::Notifications in jaeger with this setup like load_config_initializer.railties. Just not factory_bot for some reason..

I suspect what might be happening is only the first time it hits this subscribe block is the tracer creating a span. And then maybe it ignores it every time after that? I'm missing a lot of notifications I think actually.
This is not the case, even only tracking factory_bot.run_factory it doesn't show up. Maybe I'll try some different exporters.

[ahayworth]

Just so I understand - are we trying to instrument FactoryBot ? I think the duration issue might be caused because I suspect FactoryBot is caching things somehow. I haven't looked extensively through that codebase, but an initial investigation showed that they do try to memoize and skip steps when building things so it maybe what's happening. But, I'm not sure.

I think these two things might explain why you're seeing spans with OTEL_TRACES_EXPORTER=console but not with jaeger:

• When it's OTEL_TRACES_EXPORTER=jaeger, we call this bit of code and then finally fetch_exporter, which wraps your exporter in a BatchSpanProcessor.
• When it's OTEL_TRACES_EXPORTER=console, we instead use a SimpleSpanProcessor (does no batching) as you can see here.

So I suspect that when you're using jaeger, the batched spans aren't getting flushed right away. There are some environmental variables you can use here that tune the batch sizes and flush timings; you can probably get it to show up ~immediately that way.

If this is part of a test suite though, you might consider using the InMemorySpanExporter, and there are some sample usage instructions here.