Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Prevent starting Vernier in nested transactions #2528

Merged
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,7 @@
### Bug Fixes

- Fix argument serialization for ranges that consist of ActiveSupport::TimeWithZone ([#2548](https://github.com/getsentry/sentry-ruby/pull/2548))
- Prevent starting Vernier in nested transactions ([#2528](https://github.com/getsentry/sentry-ruby/pull/2528))

### Miscellaneous

Expand Down
32 changes: 31 additions & 1 deletion sentry-ruby/lib/sentry/hub.rb
Original file line number Diff line number Diff line change
Expand Up @@ -8,12 +8,42 @@ module Sentry
class Hub
include ArgumentCheckingHelper

MUTEX = Mutex.new

attr_reader :last_event_id

attr_reader :current_profiler

def initialize(client, scope)
first_layer = Layer.new(client, scope)
@stack = [first_layer]
@last_event_id = nil
@current_profiler = {}
end

# This is an internal private method
# @api private
def start_profiler!(transaction)
MUTEX.synchronize do
transaction.start_profiler!
@current_profiler[transaction.__id__] = transaction.profiler
end
end

# This is an internal private method
# @api private
def stop_profiler!(transaction)
MUTEX.synchronize do
@current_profiler.delete(transaction.__id__)&.stop
end
end

# This is an internal private method
# @api private
def profiler_running?
MUTEX.synchronize do
!@current_profiler.empty?
end
end

def new_from_top
Expand Down Expand Up @@ -96,7 +126,7 @@ def start_transaction(transaction: nil, custom_sampling_context: {}, instrumente
sampling_context.merge!(custom_sampling_context)
transaction.set_initial_sample_decision(sampling_context: sampling_context)

transaction.start_profiler!
start_profiler!(transaction)

transaction
end
Expand Down
10 changes: 8 additions & 2 deletions sentry-ruby/lib/sentry/transaction.rb
Original file line number Diff line number Diff line change
Expand Up @@ -85,7 +85,11 @@ def initialize(
@effective_sample_rate = nil
@contexts = {}
@measurements = {}
@profiler = @configuration.profiler_class.new(@configuration)

unless @hub.profiler_running?
@profiler = @configuration.profiler_class.new(@configuration)
end
Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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


init_span_recorder
end

Expand Down Expand Up @@ -257,7 +261,7 @@ def finish(hub: nil, end_timestamp: nil)
@name = UNLABELD_NAME
end

@profiler.stop
@hub.stop_profiler!(self)
Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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


if @sampled
event = hub.current_client.event_from_transaction(self)
Expand Down Expand Up @@ -299,6 +303,8 @@ def set_context(key, value)
# Start the profiler.
# @return [void]
def start_profiler!
return unless profiler

profiler.set_initial_sample_decision(sampled)
profiler.start
end
Expand Down
5 changes: 4 additions & 1 deletion sentry-ruby/lib/sentry/transaction_event.rb
Original file line number Diff line number Diff line change
Expand Up @@ -59,8 +59,11 @@ def to_hash

private

EMPTY_PROFILE = {}.freeze

def populate_profile(transaction)
profile_hash = transaction.profiler.to_hash
profile_hash = transaction.profiler&.to_hash || EMPTY_PROFILE

return if profile_hash.empty?

profile_hash.merge!(
Expand Down
5 changes: 3 additions & 2 deletions sentry-ruby/lib/sentry/vernier/profiler.rb
Original file line number Diff line number Diff line change
Expand Up @@ -74,6 +74,7 @@
return unless @started

@result = ::Vernier.stop_profile
@started = false

Check warning on line 77 in sentry-ruby/lib/sentry/vernier/profiler.rb

View check run for this annotation

Codecov / codecov/patch

sentry-ruby/lib/sentry/vernier/profiler.rb#L77

Added line #L77 was not covered by tests

log("Stopped")
rescue RuntimeError => e
Expand All @@ -89,13 +90,13 @@
end

def to_hash
return EMPTY_RESULT unless @started

unless @sampled
record_lost_event(:sample_rate)
return EMPTY_RESULT
end

return EMPTY_RESULT unless result

Check warning on line 98 in sentry-ruby/lib/sentry/vernier/profiler.rb

View check run for this annotation

Codecov / codecov/patch

sentry-ruby/lib/sentry/vernier/profiler.rb#L98

Added line #L98 was not covered by tests

{ **profile_meta, profile: output.to_h }
end

Expand Down
33 changes: 33 additions & 0 deletions sentry-ruby/spec/sentry/transactions/profiler_spec.rb
Original file line number Diff line number Diff line change
@@ -0,0 +1,33 @@
# frozen_string_literal: true

require "spec_helper"
require 'contexts/with_request_mock'

RSpec.describe Sentry, 'transactions / profiler', when: [:vernier_installed?, :rack_available?] do
include_context "with request mock"

before do
perform_basic_setup do |config|
config.traces_sample_rate = 1.0
config.profiles_sample_rate = 1.0
config.profiler_class = Sentry::Vernier::Profiler
end
end

it 'starts profiler just once inside nested transactions' do
10.times do
parent_transaction = Sentry.start_transaction(name: "parent")
nested_transaction = Sentry.start_transaction(name: "nested")

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

nested_transaction.finish
parent_transaction.finish
end
end
end
Loading