Prevent starting Vernier in nested transactions

[solnic]

Fixes #2525

I suspect this will also help with #2457

[solnic]

This thing right here is the heart of the fix, if I remove this conditional the spec I added easily reproduces the crash from the issue:

Failures:

  1) Sentry transactions / profiler starts profiler just once inside nested transactions
     Failure/Error: @stack_table_hash ||= profile._stack_table.to_h
     
     NoMethodError:
       undefined method `_stack_table' for nil
     # ./lib/sentry/vernier/output.rb:85:in `stack_table_hash'
     # ./lib/sentry/vernier/output.rb:57:in `frames'
     # ./lib/sentry/vernier/output.rb:22:in `to_h'
     # ./lib/sentry/vernier/profiler.rb:100:in `to_hash'
     # ./lib/sentry/transaction_event.rb:65:in `populate_profile'
     # ./lib/sentry/transaction_event.rb:40:in `initialize'
     # ./lib/sentry/client.rb:174:in `new'
     # ./lib/sentry/client.rb:174:in `event_from_transaction'
     # ./lib/sentry/transaction.rb:267:in `finish'
     # ./spec/sentry/transactions/profiler_spec.rb:35:in `block (3 levels) in <top (required)>'
     # ./spec/sentry/transactions/profiler_spec.rb:18:in `block (2 levels) in <top (required)>'
     # /usr/local/rvm/gems/default/gems/rspec-retry-0.6.2/lib/rspec/retry.rb:124:in `block in run'
     # /usr/local/rvm/gems/default/gems/rspec-retry-0.6.2/lib/rspec/retry.rb:110:in `run'
     # /usr/local/rvm/gems/default/gems/rspec-retry-0.6.2/lib/rspec_ext/rspec_ext.rb:12:in `run_with_retry'
     # /usr/local/rvm/gems/default/gems/rspec-retry-0.6.2/lib/rspec/retry.rb:37:in `block (2 levels) in setup'

Finished in 0.02769 seconds (files took 0.20007 seconds to load)
1 example, 1 failure

Failed examples:

rspec ./spec/sentry/transactions/profiler_spec.rb:17 # Sentry transactions / profiler starts profiler just once inside nested transactions

[codecov]

Codecov Report

Attention: Patch coverage is 90.90909% with 2 lines in your changes missing coverage. Please review.

Project coverage is 69.41%. Comparing base (1ee671c) to head (df9f4b3).

Files with missing lines	Patch %	Lines
sentry-ruby/lib/sentry/vernier/profiler.rb	0.00%	2 Missing ⚠️

Additional details and impacted files

@@            Coverage Diff             @@
##           master    #2528      +/-   ##
==========================================
+ Coverage   69.32%   69.41%   +0.08%     
==========================================
  Files         125      125              
  Lines        4721     4738      +17     
==========================================
+ Hits         3273     3289      +16     
- Misses       1448     1449       +1     

Components	Coverage Δ
sentry-ruby	60.16% <90.90%> (+0.16%)	⬆️
sentry-rails	96.76% <ø> (ø)
sentry-sidekiq	97.08% <ø> (ø)
sentry-resque	92.85% <ø> (ø)
sentry-delayed_job	95.65% <ø> (ø)
sentry-opentelemetry	99.31% <ø> (ø)

Files with missing lines	Coverage Δ
sentry-ruby/lib/sentry/hub.rb	51.30% <100.00%> (+3.55%)	⬆️
sentry-ruby/lib/sentry/transaction.rb	72.32% <100.00%> (+0.35%)	⬆️
sentry-ruby/lib/sentry/transaction_event.rb	79.48% <100.00%> (+0.53%)	⬆️
sentry-ruby/lib/sentry/vernier/profiler.rb	26.76% <0.00%> (-0.39%)	⬇️

[solnic]

Given that the hub is responsible for starting a profiler, making this change actually felt like an improvement. Transactions are coupled to hub anyway.

[st0012]

I think more of profiler related logic can actually be moved out of Transaction into Hub. I'll suggest some changes later.

[st0012]

Something like this?

diff --git a/sentry-ruby/lib/sentry/hub.rb b/sentry-ruby/lib/sentry/hub.rb
index 788e8902..a1343831 100644
--- a/sentry-ruby/lib/sentry/hub.rb
+++ b/sentry-ruby/lib/sentry/hub.rb
@@ -23,8 +23,17 @@ module Sentry
 
     def start_profiler!(transaction)
       MUTEX.synchronize do
-        transaction.start_profiler!
-        @current_profiler[transaction.__id__] = transaction.profiler
+        return if !@current_profiler.empty?
+        profiler = configuration.profiler_class.new(configuration)
+        profiler.set_initial_sample_decision(transaction.sampled)
+        profiler.start
+        @current_profiler[transaction.__id__] = profiler
+      end
+    end
+
+    def profiler_for(transaction)
+      MUTEX.synchronize do
+        @current_profiler[transaction.__id__]
       end
     end
 
@@ -34,12 +43,6 @@ module Sentry
       end
     end
 
-    def profiler_running?
-      MUTEX.synchronize do
-        !@current_profiler.empty?
-      end
-    end
-
     def new_from_top
       Hub.new(current_client, current_scope)
     end
diff --git a/sentry-ruby/lib/sentry/transaction.rb b/sentry-ruby/lib/sentry/transaction.rb
index 6fc2524b..8fc077e5 100644
--- a/sentry-ruby/lib/sentry/transaction.rb
+++ b/sentry-ruby/lib/sentry/transaction.rb
@@ -56,10 +56,6 @@ module Sentry
     # @return [Hash]
     attr_reader :contexts
 
-    # The Profiler instance for this transaction.
-    # @return [Profiler]
-    attr_reader :profiler
-
     def initialize(
       hub:,
       name: nil,
@@ -86,10 +82,6 @@ module Sentry
       @contexts = {}
       @measurements = {}
 
-      unless @hub.profiler_running?
-        @profiler = @configuration.profiler_class.new(@configuration)
-      end
-
       init_span_recorder
     end
 
@@ -300,13 +292,16 @@ module Sentry
       @contexts[key] = value
     end
 
+    # The Profiler instance for this transaction.
+    # @return [Profiler]
+    def profiler
+      @hub.profiler_for(self)
+    end
+
     # Start the profiler.
     # @return [void]
     def start_profiler!
-      return unless profiler
-
-      profiler.set_initial_sample_decision(sampled)
-      profiler.start
+      @hub.start_profiler!(self)
     end
 
     # These are high cardinality and thus bad
diff --git a/sentry-ruby/spec/sentry/transactions/profiler_spec.rb b/sentry-ruby/spec/sentry/transactions/profiler_spec.rb
index 78bb385b..fb1efd7b 100644
--- a/sentry-ruby/spec/sentry/transactions/profiler_spec.rb
+++ b/sentry-ruby/spec/sentry/transactions/profiler_spec.rb
@@ -21,8 +21,6 @@ RSpec.describe Sentry, 'transactions / profiler', when: [:vernier_installed?, :r
 
       ProfilerTest::Bar.bar
 
-      expect(Sentry.get_current_hub.profiler_running?).to be(true)
-
       expect(parent_transaction.profiler).to_not be_nil
       expect(nested_transaction.profiler).to be_nil

[sl0thentr0py]

I think more of profiler related logic can actually be moved out of Transaction into Hub. I'll suggest some changes later.

not for now since the profile is currently linked to the transaction.
Later we will have something called 'Continuous Profiling' so we can make changes then.

[solnic]

I think more of profiler related logic can actually be moved out of Transaction into Hub. I'll suggest some changes later.

I'd prefer to not make any more changes than the minimum to get the issue fixed, especially that hub doesn't expose a method for finishing a transaction, and all code that finishes transactions uses Transaction#finish, so it's the best place to stop profiling.

[st0012]

not for now since the profile is currently linked to the transaction.

and all code that finishes transactions uses Transaction#finish, so it's the best place to stop profiling.

I agree with both but I don't think my patch would change them? We can also just pass down the profiler to the transaction through a keyword argument if we want to actually retain a reference to it there.

Also, under the current implementation there's a gap between Hub#profiler_running? (thus the creation of the profiler) and Hub#start_profiler! which means that we can still have 2 profilers running at the same time?

If we only create the profiler in Hub#start_profiler! like my patch suggests, we'd avoid that problem.

[sl0thentr0py]

ok let's take a step back, is this

• only about nested transactions
• or more generally about not starting Vernier again when it's already running (globally)
  • if this is the problem, isn't it possible to ask Vernier somehow if it's currently recording? I would prefer that over adding more state into the hub to track this stuff