getsentry/sentry-ruby

Vernier profiler sometimes fails with No profile started (RuntimeError)

Closed this issue · 2 comments

grk commented

Issue Description

After switching the profiler from stackprof to vernier, some Sidekiq jobs started to fail with No profile started (RuntimeError).

Reproduction Steps

  • added the vernier gem to the Gemfile
  • set config.profiler_class = Sentry::Vernier::Profiler in sentry config
  • deployed

Not sure how our app might be different from the setup you tested on, but I'd be happy to assist with debugging.

Expected Behavior

No exceptions are raised.

Actual Behavior

Some (but not all) sidekiq jobs raise RuntimeError at the end:

RuntimeError
No profile started (RuntimeError)

vernier (1.2.1) lib/vernier.rb in stop_profile at line 51
sentry-ruby (5.21.0) lib/sentry/vernier/profiler.rb in stop at line 77
sentry-ruby (5.21.0) lib/sentry/transaction.rb in finish at line 260
sentry-sidekiq (5.21.0) lib/sentry/sidekiq/sentry_context_middleware.rb in finish_transaction at line 61
sentry-sidekiq (5.21.0) lib/sentry/sidekiq/sentry_context_middleware.rb in call at line 35
sidekiq (7.2.4) lib/sidekiq/middleware/chain.rb in traverse at line 182
sidekiq (7.2.4) lib/sidekiq/middleware/chain.rb in block in traverse at line 183
sidekiq (7.2.4) lib/sidekiq/metrics/tracking.rb in track at line 26
sidekiq (7.2.4) lib/sidekiq/metrics/tracking.rb in call at line 126
sidekiq (7.2.4) lib/sidekiq/middleware/chain.rb in traverse at line 182
sidekiq (7.2.4) lib/sidekiq/middleware/chain.rb in invoke at line 173
sidekiq (7.2.4) lib/sidekiq/processor.rb in block (3 levels) in process at line 179
sidekiq (7.2.4) lib/sidekiq/processor.rb in block (6 levels) in dispatch at line 140
sidekiq (7.2.4) lib/sidekiq/job_retry.rb in local at line 113
sidekiq (7.2.4) lib/sidekiq/processor.rb in block (5 levels) in dispatch at line 139
sidekiq (7.2.4) lib/sidekiq/rails.rb in block in call at line 16
activesupport (7.1.3.4) lib/active_support/reloader.rb in block in wrap at line 77
activesupport (7.1.3.4) lib/active_support/execution_wrapper.rb in wrap at line 92
activesupport (7.1.3.4) lib/active_support/reloader.rb in wrap at line 74
sidekiq (7.2.4) lib/sidekiq/rails.rb in call at line 15
sidekiq (7.2.4) lib/sidekiq/processor.rb in block (4 levels) in dispatch at line 135
sidekiq (7.2.4) lib/sidekiq/processor.rb in stats at line 271
sidekiq (7.2.4) lib/sidekiq/processor.rb in block (3 levels) in dispatch at line 130
sidekiq (7.2.4) lib/sidekiq/job_logger.rb in call at line 13
sidekiq (7.2.4) lib/sidekiq/processor.rb in block (2 levels) in dispatch at line 129
sidekiq (7.2.4) lib/sidekiq/job_retry.rb in global at line 80
sidekiq (7.2.4) lib/sidekiq/processor.rb in block in dispatch at line 128
sidekiq (7.2.4) lib/sidekiq/job_logger.rb in prepare at line 39
sidekiq (7.2.4) lib/sidekiq/processor.rb in dispatch at line 127
sidekiq (7.2.4) lib/sidekiq/processor.rb in block (2 levels) in process at line 178
sidekiq (7.2.4) lib/sidekiq/processor.rb in handle_interrupt at line 177
sidekiq (7.2.4) lib/sidekiq/processor.rb in block in process at line 177
sidekiq (7.2.4) lib/sidekiq/processor.rb in handle_interrupt at line 176
sidekiq (7.2.4) lib/sidekiq/processor.rb in process at line 176
sidekiq (7.2.4) lib/sidekiq/processor.rb in process_one at line 82
sidekiq (7.2.4) lib/sidekiq/processor.rb in run at line 72
sidekiq (7.2.4) lib/sidekiq/component.rb in watchdog at line 10
sidekiq (7.2.4) lib/sidekiq/component.rb in block in safe_thread at line 19

Ruby Version

3.3.2

SDK Version

5.21.0

Integration and Its Version

Rails 7.1.3.4, Sidekiq 7.2.4

Sentry Config

# frozen_string_literal: true

Sentry.init do |config|
  config.breadcrumbs_logger = [:active_support_logger]
  config.dsn = ENV['SENTRY_DSN']
  config.enable_tracing = true

  config.traces_sampler = lambda do |context|
    SystemConfig.get(:sentry_trace_sample_rate)
  end

  config.profiles_sample_rate = 0.1
  config.profiler_class = Sentry::Vernier::Profiler
end

hey thanks for reporting, I'm looking into this! 🔍 🐛

I didn't manage to reproduce but #2429 should fix it. I suspect that it's a race condition during job retry when vernier is start/stopping while sentry's profiler was trying to stop it pre-maturely.