From 77d645b2fa5e07ab8994e1c3286356ed55215f2d Mon Sep 17 00:00:00 2001 From: Neel Shah Date: Mon, 20 Mar 2023 20:39:19 +0100 Subject: [PATCH 01/18] WIP --- sentry-ruby/lib/sentry/envelope.rb | 5 +- sentry-ruby/lib/sentry/hub.rb | 4 + sentry-ruby/lib/sentry/profiler.rb | 135 ++++++++++++++++++++ sentry-ruby/lib/sentry/scope.rb | 3 +- sentry-ruby/lib/sentry/transaction.rb | 11 ++ sentry-ruby/lib/sentry/transaction_event.rb | 31 +++++ sentry-ruby/lib/sentry/transport.rb | 8 ++ sentry-ruby/sentry-ruby.gemspec | 2 + 8 files changed, 194 insertions(+), 5 deletions(-) create mode 100644 sentry-ruby/lib/sentry/profiler.rb diff --git a/sentry-ruby/lib/sentry/envelope.rb b/sentry-ruby/lib/sentry/envelope.rb index 11e62d925..54da999e1 100644 --- a/sentry-ruby/lib/sentry/envelope.rb +++ b/sentry-ruby/lib/sentry/envelope.rb @@ -19,10 +19,7 @@ def type end def to_s - <<~ITEM - #{JSON.generate(@headers)} - #{JSON.generate(@payload)} - ITEM + [JSON.generate(@headers), JSON.generate(@payload)].join("\n") end def serialize diff --git a/sentry-ruby/lib/sentry/hub.rb b/sentry-ruby/lib/sentry/hub.rb index 8f0a14d23..69a1b5a95 100644 --- a/sentry-ruby/lib/sentry/hub.rb +++ b/sentry-ruby/lib/sentry/hub.rb @@ -90,6 +90,10 @@ def start_transaction(transaction: nil, custom_sampling_context: {}, instrumente sampling_context.merge!(custom_sampling_context) transaction.set_initial_sample_decision(sampling_context: sampling_context) + + #TODO-neel-profiler sample + transaction.profiler.start + transaction end diff --git a/sentry-ruby/lib/sentry/profiler.rb b/sentry-ruby/lib/sentry/profiler.rb new file mode 100644 index 000000000..a7cf5feb6 --- /dev/null +++ b/sentry-ruby/lib/sentry/profiler.rb @@ -0,0 +1,135 @@ +# frozen_string_literal: true + +require 'etc' +require 'stackprof' +require 'securerandom' + +module Sentry + class Profiler + + VERSION = '1' + PLATFORM = 'ruby' + # 101 Hz in microseconds + DEFAULT_INTERVAL = 1e6 / 101 + + def initialize + @event_id = SecureRandom.uuid.delete('-') + @started = false + end + + def start + @started = StackProf.start(interval: DEFAULT_INTERVAL, + mode: :wall, + raw: true, + aggregate: false) + + @started ? log('Started') : log('Not started since running elsewhere') + end + + def stop + return unless @started + + StackProf.stop + log('Stopped') + end + + def to_hash + return nil unless Sentry.initialized? + return nil unless @started + + results = StackProf.results + return nil unless results + return nil if results.empty? + + frame_map = {} + + frames = results[:frames].to_enum.with_index.map do |frame, idx| + frame_id, frame_data = frame + + # need to map over stackprof frame ids to ours + frame_map[frame_id] = idx + + # TODO-neel module, filename, in_app + { + abs_path: frame_data[:file], + function: frame_data[:name], + lineno: frame_data[:line] + }.compact + end + + idx = 0 + stacks = [] + num_seen = [] + + # extract stacks from raw + # raw is a single array of [.., len_stack, *stack_frames(len_stack), num_stack_seen , ..] + while (len = results[:raw][idx]) + idx += 1 + + # our call graph is reversed + stack = results[:raw].slice(idx, len).map { |id| frame_map[id] }.compact.reverse + stacks << stack + + num_seen << results[:raw][idx + len] + idx += len + 1 + + log('Unknown frame in stack') if stack.size != len + end + + idx = 0 + elapsed_since_start_ns = 0 + samples = [] + + num_seen.each_with_index do |n, i| + n.times do + # stackprof deltas are in microseconds + delta = results[:raw_timestamp_deltas][idx] + elapsed_since_start_ns += (delta * 1e3).to_i + idx += 1 + + # Not sure why but some deltas are very small like 0/1 values, + # they pollute our flamegraph so just ignore them for now. + # Open issue at https://github.com/tmm1/stackprof/issues/201 + next if delta < 10 + + samples << { + stack_id: i, + # TODO-neel we need to patch rb_profile_frames and write our own C extension to enable threading info + # till then, on multi-threaded servers like puma, we will get frames from other active threads when the one + # we're profiling is idle/sleeping/waiting for IO etc + # https://bugs.ruby-lang.org/issues/10602 + thread_id: '0', + elapsed_since_start_ns: elapsed_since_start_ns.to_s + } + end + end + + log('Some samples thrown away') if samples.size != results[:samples] + + if samples.size <= 2 + log('Not enough samples, discarding profiler') + return nil + end + + profile = { + frames: frames, + stacks: stacks, + samples: samples + } + + { + event_id: @event_id, + platform: PLATFORM, + version: VERSION, + profile: profile + } + end + + private + + def log(message) + Sentry.logger.debug(LOGGER_PROGNAME) { "[Profiler] #{message}" } + end + + end +end diff --git a/sentry-ruby/lib/sentry/scope.rb b/sentry-ruby/lib/sentry/scope.rb index 3e2dfb02b..7f98cd079 100644 --- a/sentry-ruby/lib/sentry/scope.rb +++ b/sentry-ruby/lib/sentry/scope.rb @@ -309,7 +309,8 @@ def os_context name: uname[:sysname] || RbConfig::CONFIG["host_os"], version: uname[:version], build: uname[:release], - kernel_version: uname[:version] + kernel_version: uname[:version], + machine: uname[:machine] } end end diff --git a/sentry-ruby/lib/sentry/transaction.rb b/sentry-ruby/lib/sentry/transaction.rb index 52efa6fe6..ba0ca5470 100644 --- a/sentry-ruby/lib/sentry/transaction.rb +++ b/sentry-ruby/lib/sentry/transaction.rb @@ -1,6 +1,7 @@ # frozen_string_literal: true require "sentry/baggage" +require "sentry/profiler" module Sentry class Transaction < Span @@ -83,6 +84,7 @@ def initialize( @effective_sample_rate = nil @contexts = {} @measurements = {} + @profiler = nil init_span_recorder end @@ -254,6 +256,9 @@ def finish(hub: nil, end_timestamp: nil) @name = UNLABELD_NAME end + # TODO-neel-profiler sample + @profiler&.stop + if @sampled event = hub.current_client.event_from_transaction(self) hub.capture_event(event) @@ -288,6 +293,12 @@ def set_context(key, value) @contexts[key] = value end + # The stackprof profiler instance + # @return [Profiler] + def profiler + @profiler ||= Profiler.new + end + protected def init_span_recorder(limit = 1000) diff --git a/sentry-ruby/lib/sentry/transaction_event.rb b/sentry-ruby/lib/sentry/transaction_event.rb index 4eaaa0282..2cd76693b 100644 --- a/sentry-ruby/lib/sentry/transaction_event.rb +++ b/sentry-ruby/lib/sentry/transaction_event.rb @@ -17,6 +17,9 @@ class TransactionEvent < Event # @return [Float, nil] attr_reader :start_timestamp + # @return [Hash, nil] + attr_accessor :profile + def initialize(transaction:, **options) super(**options) @@ -32,6 +35,9 @@ def initialize(transaction:, **options) finished_spans = transaction.span_recorder.spans.select { |span| span.timestamp && span != transaction } self.spans = finished_spans.map(&:to_hash) + + # TODO-neel-profiler cleanup sampling etc + self.profile = populate_profile(transaction) end # Sets the event's start_timestamp. @@ -49,5 +55,30 @@ def to_hash data[:measurements] = @measurements data end + + private + + def populate_profile(transaction) + return nil unless transaction.profiler + + profile = transaction.profiler.to_hash + return nil unless profile + + profile.merge( + environment: environment, + release: release, + timestamp: Time.at(start_timestamp).iso8601, + device: { architecture: Scope.os_context[:machine] }, + os: { name: Scope.os_context[:name], version: Scope.os_context[:version] }, + runtime: Scope.runtime_context, + transaction: { + id: event_id, + name: transaction.name, + trace_id: transaction.trace_id, + # TODO-neel-profiler stubbed for now, see thread_id note in profiler.rb + active_thead_id: '0' + } + ) + end end end diff --git a/sentry-ruby/lib/sentry/transport.rb b/sentry-ruby/lib/sentry/transport.rb index a01c903cb..2c217ab87 100644 --- a/sentry-ruby/lib/sentry/transport.rb +++ b/sentry-ruby/lib/sentry/transport.rb @@ -61,6 +61,7 @@ def send_envelope(envelope) if data log_info("[Transport] Sending envelope with items [#{serialized_items.map(&:type).join(', ')}] #{envelope.event_id} to Sentry") + File.open('/tmp/dump', 'w') { |file| file.write(data) } if envelope.items.map(&:type).include?('profile') send_data(data) end end @@ -154,6 +155,13 @@ def envelope_from_event(event) event_payload ) + if event.is_a?(TransactionEvent) && event.profile + envelope.add_item( + { type: 'profile', content_type: 'application/json' }, + event.profile + ) + end + client_report_headers, client_report_payload = fetch_pending_client_report envelope.add_item(client_report_headers, client_report_payload) if client_report_headers diff --git a/sentry-ruby/sentry-ruby.gemspec b/sentry-ruby/sentry-ruby.gemspec index 154d7638c..62b0cd136 100644 --- a/sentry-ruby/sentry-ruby.gemspec +++ b/sentry-ruby/sentry-ruby.gemspec @@ -21,4 +21,6 @@ Gem::Specification.new do |spec| spec.require_paths = ["lib"] spec.add_dependency "concurrent-ruby", '~> 1.0', '>= 1.0.2' + # TODO-neel-profiler make peer dep + spec.add_dependency "stackprof", '~> 0.2.23' end From d5ca8c4df944f8c8c09809ac8a47d90a20e43c8d Mon Sep 17 00:00:00 2001 From: Neel Shah Date: Thu, 30 Mar 2023 14:05:35 +0200 Subject: [PATCH 02/18] Make stackprof peer dep --- sentry-ruby/lib/sentry/hub.rb | 2 +- sentry-ruby/lib/sentry/profiler.rb | 204 +++++++++++++------------- sentry-ruby/lib/sentry/transaction.rb | 4 +- sentry-ruby/sentry-ruby.gemspec | 2 - 4 files changed, 106 insertions(+), 106 deletions(-) diff --git a/sentry-ruby/lib/sentry/hub.rb b/sentry-ruby/lib/sentry/hub.rb index 69a1b5a95..9b9f2d7e8 100644 --- a/sentry-ruby/lib/sentry/hub.rb +++ b/sentry-ruby/lib/sentry/hub.rb @@ -92,7 +92,7 @@ def start_transaction(transaction: nil, custom_sampling_context: {}, instrumente transaction.set_initial_sample_decision(sampling_context: sampling_context) #TODO-neel-profiler sample - transaction.profiler.start + transaction.profiler&.start transaction end diff --git a/sentry-ruby/lib/sentry/profiler.rb b/sentry-ruby/lib/sentry/profiler.rb index a7cf5feb6..b0797d29f 100644 --- a/sentry-ruby/lib/sentry/profiler.rb +++ b/sentry-ruby/lib/sentry/profiler.rb @@ -1,135 +1,135 @@ # frozen_string_literal: true -require 'etc' -require 'stackprof' -require 'securerandom' +if defined?(StackProf) + require 'securerandom' -module Sentry - class Profiler + module Sentry + class Profiler - VERSION = '1' - PLATFORM = 'ruby' - # 101 Hz in microseconds - DEFAULT_INTERVAL = 1e6 / 101 + VERSION = '1' + PLATFORM = 'ruby' + # 101 Hz in microseconds + DEFAULT_INTERVAL = 1e6 / 101 - def initialize - @event_id = SecureRandom.uuid.delete('-') - @started = false - end + def initialize + @event_id = SecureRandom.uuid.delete('-') + @started = false + end - def start - @started = StackProf.start(interval: DEFAULT_INTERVAL, - mode: :wall, - raw: true, - aggregate: false) + def start + @started = StackProf.start(interval: DEFAULT_INTERVAL, + mode: :wall, + raw: true, + aggregate: false) - @started ? log('Started') : log('Not started since running elsewhere') - end + @started ? log('Started') : log('Not started since running elsewhere') + end - def stop - return unless @started + def stop + return unless @started - StackProf.stop - log('Stopped') - end + StackProf.stop + log('Stopped') + end - def to_hash - return nil unless Sentry.initialized? - return nil unless @started + def to_hash + return nil unless Sentry.initialized? + return nil unless @started - results = StackProf.results - return nil unless results - return nil if results.empty? + results = StackProf.results + return nil unless results + return nil if results.empty? - frame_map = {} + frame_map = {} - frames = results[:frames].to_enum.with_index.map do |frame, idx| - frame_id, frame_data = frame + frames = results[:frames].to_enum.with_index.map do |frame, idx| + frame_id, frame_data = frame - # need to map over stackprof frame ids to ours - frame_map[frame_id] = idx + # need to map over stackprof frame ids to ours + frame_map[frame_id] = idx - # TODO-neel module, filename, in_app - { - abs_path: frame_data[:file], - function: frame_data[:name], - lineno: frame_data[:line] - }.compact - end + # TODO-neel module, filename, in_app + { + abs_path: frame_data[:file], + function: frame_data[:name], + lineno: frame_data[:line] + }.compact + end - idx = 0 - stacks = [] - num_seen = [] + idx = 0 + stacks = [] + num_seen = [] - # extract stacks from raw - # raw is a single array of [.., len_stack, *stack_frames(len_stack), num_stack_seen , ..] - while (len = results[:raw][idx]) - idx += 1 + # extract stacks from raw + # raw is a single array of [.., len_stack, *stack_frames(len_stack), num_stack_seen , ..] + while (len = results[:raw][idx]) + idx += 1 - # our call graph is reversed - stack = results[:raw].slice(idx, len).map { |id| frame_map[id] }.compact.reverse - stacks << stack + # our call graph is reversed + stack = results[:raw].slice(idx, len).map { |id| frame_map[id] }.compact.reverse + stacks << stack - num_seen << results[:raw][idx + len] - idx += len + 1 + num_seen << results[:raw][idx + len] + idx += len + 1 - log('Unknown frame in stack') if stack.size != len - end + log('Unknown frame in stack') if stack.size != len + end - idx = 0 - elapsed_since_start_ns = 0 - samples = [] + idx = 0 + elapsed_since_start_ns = 0 + samples = [] + + num_seen.each_with_index do |n, i| + n.times do + # stackprof deltas are in microseconds + delta = results[:raw_timestamp_deltas][idx] + elapsed_since_start_ns += (delta * 1e3).to_i + idx += 1 + + # Not sure why but some deltas are very small like 0/1 values, + # they pollute our flamegraph so just ignore them for now. + # Open issue at https://github.com/tmm1/stackprof/issues/201 + next if delta < 10 + + samples << { + stack_id: i, + # TODO-neel we need to patch rb_profile_frames and write our own C extension to enable threading info + # till then, on multi-threaded servers like puma, we will get frames from other active threads when the one + # we're profiling is idle/sleeping/waiting for IO etc + # https://bugs.ruby-lang.org/issues/10602 + thread_id: '0', + elapsed_since_start_ns: elapsed_since_start_ns.to_s + } + end + end - num_seen.each_with_index do |n, i| - n.times do - # stackprof deltas are in microseconds - delta = results[:raw_timestamp_deltas][idx] - elapsed_since_start_ns += (delta * 1e3).to_i - idx += 1 + log('Some samples thrown away') if samples.size != results[:samples] - # Not sure why but some deltas are very small like 0/1 values, - # they pollute our flamegraph so just ignore them for now. - # Open issue at https://github.com/tmm1/stackprof/issues/201 - next if delta < 10 - - samples << { - stack_id: i, - # TODO-neel we need to patch rb_profile_frames and write our own C extension to enable threading info - # till then, on multi-threaded servers like puma, we will get frames from other active threads when the one - # we're profiling is idle/sleeping/waiting for IO etc - # https://bugs.ruby-lang.org/issues/10602 - thread_id: '0', - elapsed_since_start_ns: elapsed_since_start_ns.to_s - } + if samples.size <= 2 + log('Not enough samples, discarding profiler') + return nil end - end - log('Some samples thrown away') if samples.size != results[:samples] + profile = { + frames: frames, + stacks: stacks, + samples: samples + } - if samples.size <= 2 - log('Not enough samples, discarding profiler') - return nil + { + event_id: @event_id, + platform: PLATFORM, + version: VERSION, + profile: profile + } end - profile = { - frames: frames, - stacks: stacks, - samples: samples - } - - { - event_id: @event_id, - platform: PLATFORM, - version: VERSION, - profile: profile - } - end + private - private + def log(message) + Sentry.logger.debug(LOGGER_PROGNAME) { "[Profiler] #{message}" } + end - def log(message) - Sentry.logger.debug(LOGGER_PROGNAME) { "[Profiler] #{message}" } end - end end diff --git a/sentry-ruby/lib/sentry/transaction.rb b/sentry-ruby/lib/sentry/transaction.rb index ba0ca5470..59a5bfe47 100644 --- a/sentry-ruby/lib/sentry/transaction.rb +++ b/sentry-ruby/lib/sentry/transaction.rb @@ -294,8 +294,10 @@ def set_context(key, value) end # The stackprof profiler instance - # @return [Profiler] + # @return [Profiler, nil] def profiler + return nil unless defined?(Profiler) + @profiler ||= Profiler.new end diff --git a/sentry-ruby/sentry-ruby.gemspec b/sentry-ruby/sentry-ruby.gemspec index 62b0cd136..154d7638c 100644 --- a/sentry-ruby/sentry-ruby.gemspec +++ b/sentry-ruby/sentry-ruby.gemspec @@ -21,6 +21,4 @@ Gem::Specification.new do |spec| spec.require_paths = ["lib"] spec.add_dependency "concurrent-ruby", '~> 1.0', '>= 1.0.2' - # TODO-neel-profiler make peer dep - spec.add_dependency "stackprof", '~> 0.2.23' end From dbc504d4722a7436e92051a65eff4e9154c134ef Mon Sep 17 00:00:00 2001 From: Neel Shah Date: Thu, 30 Mar 2023 15:34:17 +0200 Subject: [PATCH 03/18] Implement sampling --- sentry-ruby/lib/sentry/configuration.rb | 26 +++++++++++++ sentry-ruby/lib/sentry/hub.rb | 6 ++- sentry-ruby/lib/sentry/profiler.rb | 43 ++++++++++++++++++++- sentry-ruby/lib/sentry/transaction.rb | 1 - sentry-ruby/lib/sentry/transaction_event.rb | 2 +- 5 files changed, 73 insertions(+), 5 deletions(-) diff --git a/sentry-ruby/lib/sentry/configuration.rb b/sentry-ruby/lib/sentry/configuration.rb index a4dd30042..2f919aa76 100644 --- a/sentry-ruby/lib/sentry/configuration.rb +++ b/sentry-ruby/lib/sentry/configuration.rb @@ -245,6 +245,12 @@ def capture_exception_frame_locals=(value) # @return [Symbol] attr_reader :instrumenter + # Take a float between 0.0 and 1.0 as the sample rate for capturing profiles. + # Note that this rate is relative to traces_sample_rate / traces_sampler, + # i.e. the profile is sampled by this rate after the transaction is sampled. + # @return [Float, nil] + attr_reader :profiles_sample_rate + # these are not config options # @!visibility private attr_reader :errors, :gem_specs @@ -395,6 +401,18 @@ def enable_tracing=(enable_tracing) @traces_sample_rate ||= 1.0 if enable_tracing end + def profiles_sample_rate=(profiles_sample_rate) + log_info("Thank you for trying out Profiling on Sentry. Please note that this is currently an experimental feature.") + + if defined?(StackProf) + log_info("Feedback on how it is working for you is appreciated!") + else + log_info("Please make sure to include the 'stackprof' gem in your Gemfile to use Profiling with Sentry.") + end + + @profiles_sample_rate = profiles_sample_rate + end + def sending_allowed? @errors = [] @@ -433,6 +451,14 @@ def tracing_enabled? (@enable_tracing != false) && valid_sampler && sending_allowed? end + def profiling_enabled? + valid_sampler = !!(@profiles_sample_rate && + @profiles_sample_rate >= 0.0 && + @profiles_sample_rate <= 1.0) + + tracing_enabled? && valid_sampler && sending_allowed? + end + # @return [String, nil] def csp_report_uri if dsn && dsn.valid? diff --git a/sentry-ruby/lib/sentry/hub.rb b/sentry-ruby/lib/sentry/hub.rb index 9b9f2d7e8..98811fc8b 100644 --- a/sentry-ruby/lib/sentry/hub.rb +++ b/sentry-ruby/lib/sentry/hub.rb @@ -91,8 +91,10 @@ def start_transaction(transaction: nil, custom_sampling_context: {}, instrumente transaction.set_initial_sample_decision(sampling_context: sampling_context) - #TODO-neel-profiler sample - transaction.profiler&.start + if transaction.profiler + transaction.profiler.set_initial_sample_decision(transaction.sampled) + transaction.profiler.start + end transaction end diff --git a/sentry-ruby/lib/sentry/profiler.rb b/sentry-ruby/lib/sentry/profiler.rb index b0797d29f..05def233c 100644 --- a/sentry-ruby/lib/sentry/profiler.rb +++ b/sentry-ruby/lib/sentry/profiler.rb @@ -12,11 +12,16 @@ class Profiler DEFAULT_INTERVAL = 1e6 / 101 def initialize + @profiling_enabled = Sentry.configuration.profiling_enabled? + @profiles_sample_rate = Sentry.configuration.profiles_sample_rate @event_id = SecureRandom.uuid.delete('-') @started = false + @sampled = nil end def start + return unless @sampled + @started = StackProf.start(interval: DEFAULT_INTERVAL, mode: :wall, raw: true, @@ -26,14 +31,50 @@ def start end def stop + return unless @sampled return unless @started StackProf.stop log('Stopped') end + # Sets initial sampling decision of the profile. + # @return [void] + def set_initial_sample_decision(transaction_sampled) + unless @profiling_enabled + @sampled = false + return + end + + unless transaction_sampled + @sampled = false + log('Discarding profile because transaction not sampled') + return + end + + if @profiles_sample_rate < 0.0 || @profiles_sample_rate > 1.0 + @sampled = false + log("Discarding profile because of invalid sample_rate: #{@profiles_sample_rate}") + return + end + + case @profiles_sample_rate + when 0.0 + @sampled = false + log('Discarding profile because sample_rate is 0') + return + when 1.0 + @sampled = true + return + else + @sampled = Random.rand < @profiles_sample_rate + end + + log('Discarding profile due to sampling decision') unless @sampled + end + def to_hash - return nil unless Sentry.initialized? + return nil unless @sampled return nil unless @started results = StackProf.results diff --git a/sentry-ruby/lib/sentry/transaction.rb b/sentry-ruby/lib/sentry/transaction.rb index 59a5bfe47..1b529a0ad 100644 --- a/sentry-ruby/lib/sentry/transaction.rb +++ b/sentry-ruby/lib/sentry/transaction.rb @@ -256,7 +256,6 @@ def finish(hub: nil, end_timestamp: nil) @name = UNLABELD_NAME end - # TODO-neel-profiler sample @profiler&.stop if @sampled diff --git a/sentry-ruby/lib/sentry/transaction_event.rb b/sentry-ruby/lib/sentry/transaction_event.rb index 2cd76693b..f28ec35fa 100644 --- a/sentry-ruby/lib/sentry/transaction_event.rb +++ b/sentry-ruby/lib/sentry/transaction_event.rb @@ -36,7 +36,7 @@ def initialize(transaction:, **options) finished_spans = transaction.span_recorder.spans.select { |span| span.timestamp && span != transaction } self.spans = finished_spans.map(&:to_hash) - # TODO-neel-profiler cleanup sampling etc + # TODO-neel-profiler profiling context self.profile = populate_profile(transaction) end From 1b5046dde702038780061a33e16311d58504f22b Mon Sep 17 00:00:00 2001 From: Neel Shah Date: Thu, 30 Mar 2023 15:37:11 +0200 Subject: [PATCH 04/18] Fix scope specs --- sentry-ruby/spec/sentry/scope_spec.rb | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/sentry-ruby/spec/sentry/scope_spec.rb b/sentry-ruby/spec/sentry/scope_spec.rb index a075b963b..1e6d92426 100644 --- a/sentry-ruby/spec/sentry/scope_spec.rb +++ b/sentry-ruby/spec/sentry/scope_spec.rb @@ -16,7 +16,7 @@ describe "#initialize" do it "contains correct defaults" do expect(subject.breadcrumbs).to be_a(Sentry::BreadcrumbBuffer) - expect(subject.contexts[:os].keys).to match_array([:name, :version, :build, :kernel_version]) + expect(subject.contexts[:os].keys).to match_array([:name, :version, :build, :kernel_version, :machine]) expect(subject.contexts.dig(:runtime, :version)).to match(/ruby/) expect(subject.extra).to eq({}) expect(subject.tags).to eq({}) @@ -46,7 +46,7 @@ copy.fingerprint << "bar" expect(subject.breadcrumbs.to_hash).to eq({ values: [] }) - expect(subject.contexts[:os].keys).to match_array([:name, :version, :build, :kernel_version]) + expect(subject.contexts[:os].keys).to match_array([:name, :version, :build, :kernel_version, :machine]) expect(subject.contexts.dig(:runtime, :version)).to match(/ruby/) expect(subject.extra).to eq({}) expect(subject.tags).to eq({}) @@ -136,7 +136,7 @@ expect(subject.object_id).to eq(scope_id) expect(subject.breadcrumbs).to be_a(Sentry::BreadcrumbBuffer) - expect(subject.contexts[:os].keys).to match_array([:name, :version, :build, :kernel_version]) + expect(subject.contexts[:os].keys).to match_array([:name, :version, :build, :kernel_version, :machine]) expect(subject.contexts.dig(:runtime, :version)).to match(/ruby/) expect(subject.extra).to eq({}) expect(subject.tags).to eq({}) @@ -217,7 +217,7 @@ expect(event.transaction_info).to eq({ source: :view }) expect(event.breadcrumbs).to be_a(Sentry::BreadcrumbBuffer) expect(event.fingerprint).to eq(["foo"]) - expect(event.contexts[:os].keys).to match_array([:name, :version, :build, :kernel_version]) + expect(event.contexts[:os].keys).to match_array([:name, :version, :build, :kernel_version, :machine]) expect(event.contexts.dig(:runtime, :version)).to match(/ruby/) end From 621414a4a8713f6cb2d00253b9f94a4db63ed799 Mon Sep 17 00:00:00 2001 From: Neel Shah Date: Thu, 30 Mar 2023 16:29:39 +0200 Subject: [PATCH 05/18] Add profiling context --- sentry-ruby/lib/sentry/profiler.rb | 10 +++++++--- sentry-ruby/lib/sentry/transaction_event.rb | 12 +++++++----- 2 files changed, 14 insertions(+), 8 deletions(-) diff --git a/sentry-ruby/lib/sentry/profiler.rb b/sentry-ruby/lib/sentry/profiler.rb index 05def233c..214350131 100644 --- a/sentry-ruby/lib/sentry/profiler.rb +++ b/sentry-ruby/lib/sentry/profiler.rb @@ -38,6 +38,10 @@ def stop log('Stopped') end + def profile_context + { profile_id: @event_id } + end + # Sets initial sampling decision of the profile. # @return [void] def set_initial_sample_decision(transaction_sampled) @@ -134,9 +138,9 @@ def to_hash samples << { stack_id: i, - # TODO-neel we need to patch rb_profile_frames and write our own C extension to enable threading info - # till then, on multi-threaded servers like puma, we will get frames from other active threads when the one - # we're profiling is idle/sleeping/waiting for IO etc + # TODO-neel we need to patch rb_profile_frames and write our own C extension to enable threading info. + # Till then, on multi-threaded servers like puma, we will get frames from other active threads when the one + # we're profiling is idle/sleeping/waiting for IO etc. # https://bugs.ruby-lang.org/issues/10602 thread_id: '0', elapsed_since_start_ns: elapsed_since_start_ns.to_s diff --git a/sentry-ruby/lib/sentry/transaction_event.rb b/sentry-ruby/lib/sentry/transaction_event.rb index f28ec35fa..1ac0950b4 100644 --- a/sentry-ruby/lib/sentry/transaction_event.rb +++ b/sentry-ruby/lib/sentry/transaction_event.rb @@ -36,8 +36,7 @@ def initialize(transaction:, **options) finished_spans = transaction.span_recorder.spans.select { |span| span.timestamp && span != transaction } self.spans = finished_spans.map(&:to_hash) - # TODO-neel-profiler profiling context - self.profile = populate_profile(transaction) + populate_profile(transaction) end # Sets the event's start_timestamp. @@ -61,10 +60,10 @@ def to_hash def populate_profile(transaction) return nil unless transaction.profiler - profile = transaction.profiler.to_hash - return nil unless profile + profile_hash = transaction.profiler.to_hash + return nil unless profile_hash - profile.merge( + profile_hash.merge!( environment: environment, release: release, timestamp: Time.at(start_timestamp).iso8601, @@ -79,6 +78,9 @@ def populate_profile(transaction) active_thead_id: '0' } ) + + self.profile = profile_hash + self.contexts.merge!(profile: transaction.profiler.profile_context) end end end From e07925f3469bf6b7a022af43e9793724c4a3c3cd Mon Sep 17 00:00:00 2001 From: Neel Shah Date: Thu, 30 Mar 2023 17:59:24 +0200 Subject: [PATCH 06/18] Add module/function/filename/in_app processing --- sentry-ruby/lib/sentry/profiler.rb | 55 +++++++++++++++++++++++++++--- 1 file changed, 51 insertions(+), 4 deletions(-) diff --git a/sentry-ruby/lib/sentry/profiler.rb b/sentry-ruby/lib/sentry/profiler.rb index 214350131..4804305f8 100644 --- a/sentry-ruby/lib/sentry/profiler.rb +++ b/sentry-ruby/lib/sentry/profiler.rb @@ -14,6 +14,11 @@ class Profiler def initialize @profiling_enabled = Sentry.configuration.profiling_enabled? @profiles_sample_rate = Sentry.configuration.profiles_sample_rate + + @project_root = Sentry.configuration.project_root + @app_dirs_pattern = Sentry.configuration.app_dirs_pattern + @in_app_pattern = Regexp.new("^(#{@project_root}/)?#{@app_dirs_pattern || Backtrace::APP_DIRS_PATTERN}") + @event_id = SecureRandom.uuid.delete('-') @started = false @sampled = nil @@ -93,11 +98,17 @@ def to_hash # need to map over stackprof frame ids to ours frame_map[frame_id] = idx - # TODO-neel module, filename, in_app + in_app = in_app?(frame_data[:file]) + filename = compute_filename(frame_data[:file], in_app) + function, mod = split_module(frame_data[:name]) + { abs_path: frame_data[:file], - function: frame_data[:name], - lineno: frame_data[:line] + function: function, + module: mod, + lineno: frame_data[:line], + filename: filename, + in_app: in_app }.compact end @@ -138,7 +149,7 @@ def to_hash samples << { stack_id: i, - # TODO-neel we need to patch rb_profile_frames and write our own C extension to enable threading info. + # TODO-neel-profiler we need to patch rb_profile_frames and write our own C extension to enable threading info. # Till then, on multi-threaded servers like puma, we will get frames from other active threads when the one # we're profiling is idle/sleeping/waiting for IO etc. # https://bugs.ruby-lang.org/issues/10602 @@ -175,6 +186,42 @@ def log(message) Sentry.logger.debug(LOGGER_PROGNAME) { "[Profiler] #{message}" } end + def in_app?(abs_path) + abs_path.match?(@in_app_pattern) + end + + # copied from stacktrace.rb since I don't want to touch existing code + # TODO-neel-profiler try to fetch this from stackprof once we patch + # the native extension + def compute_filename(abs_path, in_app) + return nil if abs_path.nil? + + under_project_root = @project_root && abs_path.start_with?(@project_root) + + prefix = + if under_project_root && in_app + @project_root + else + longest_load_path = $LOAD_PATH.select { |path| abs_path.start_with?(path.to_s) }.max_by(&:size) + + if under_project_root + longest_load_path || @project_root + else + longest_load_path + end + end + + prefix ? abs_path[prefix.to_s.chomp(File::SEPARATOR).length + 1..-1] : abs_path + end + + def split_module(name) + # last module plus class/instance method + i = name.rindex('::') + function = i ? name[(i + 2)..-1] : name + mod = i ? name[0...i] : nil + + [function, mod] + end end end end From 6ebe2b7508a75cde01aca9662c73ea9fac49e0ca Mon Sep 17 00:00:00 2001 From: Neel Shah Date: Wed, 5 Apr 2023 16:54:54 +0200 Subject: [PATCH 07/18] Specs --- CHANGELOG.md | 1 + sentry-ruby/Gemfile | 1 + sentry-ruby/lib/sentry/profiler.rb | 353 +++++++++--------- sentry-ruby/lib/sentry/transport.rb | 1 - sentry-ruby/spec/sentry/configuration_spec.rb | 34 ++ sentry-ruby/spec/sentry/profiler_spec.rb | 262 +++++++++++++ .../sentry/rack/capture_exceptions_spec.rb | 68 +++- sentry-ruby/spec/sentry/transport_spec.rb | 54 +++ sentry-ruby/spec/spec_helper.rb | 1 + .../spec/support/stackprof_results.json | 1 + 10 files changed, 600 insertions(+), 176 deletions(-) create mode 100644 sentry-ruby/spec/sentry/profiler_spec.rb create mode 100644 sentry-ruby/spec/support/stackprof_results.json diff --git a/CHANGELOG.md b/CHANGELOG.md index ba98549ca..0480a507b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -16,6 +16,7 @@ ``` - Add `spec` to `Backtrace::APP_DIRS_PATTERN` [#2029](https://github.com/getsentry/sentry-ruby/pull/2029) - Forward all `baggage` header items that are prefixed with `sentry-` [#2025](https://github.com/getsentry/sentry-ruby/pull/2025) +- Profiling TODO-neel-profiler changelog entry ### Bug Fixes diff --git a/sentry-ruby/Gemfile b/sentry-ruby/Gemfile index a6f1ea99f..51bb73f88 100644 --- a/sentry-ruby/Gemfile +++ b/sentry-ruby/Gemfile @@ -17,6 +17,7 @@ gem "timecop" gem "simplecov" gem "simplecov-cobertura", "~> 1.4" gem "rexml" +gem "stackprof" unless RUBY_PLATFORM == "java" gem "object_tracer" gem "debug", github: "ruby/debug", platform: :ruby if RUBY_VERSION.to_f >= 2.6 diff --git a/sentry-ruby/lib/sentry/profiler.rb b/sentry-ruby/lib/sentry/profiler.rb index 4804305f8..df5276904 100644 --- a/sentry-ruby/lib/sentry/profiler.rb +++ b/sentry-ruby/lib/sentry/profiler.rb @@ -1,227 +1,232 @@ # frozen_string_literal: true -if defined?(StackProf) - require 'securerandom' +return unless defined?(StackProf) - module Sentry - class Profiler +require 'securerandom' - VERSION = '1' - PLATFORM = 'ruby' - # 101 Hz in microseconds - DEFAULT_INTERVAL = 1e6 / 101 +module Sentry + class Profiler - def initialize - @profiling_enabled = Sentry.configuration.profiling_enabled? - @profiles_sample_rate = Sentry.configuration.profiles_sample_rate + VERSION = '1' + PLATFORM = 'ruby' + # 101 Hz in microseconds + DEFAULT_INTERVAL = 1e6 / 101 - @project_root = Sentry.configuration.project_root - @app_dirs_pattern = Sentry.configuration.app_dirs_pattern - @in_app_pattern = Regexp.new("^(#{@project_root}/)?#{@app_dirs_pattern || Backtrace::APP_DIRS_PATTERN}") + attr_reader :sampled, :started, :event_id - @event_id = SecureRandom.uuid.delete('-') - @started = false - @sampled = nil - end + def initialize + @event_id = SecureRandom.uuid.delete('-') + @started = false + @sampled = nil + end - def start - return unless @sampled + def start + return unless @sampled - @started = StackProf.start(interval: DEFAULT_INTERVAL, - mode: :wall, - raw: true, - aggregate: false) + @started = StackProf.start(interval: DEFAULT_INTERVAL, + mode: :wall, + raw: true, + aggregate: false) - @started ? log('Started') : log('Not started since running elsewhere') - end + @started ? log('Started') : log('Not started since running elsewhere') + end + + def stop + return unless @sampled + return unless @started - def stop - return unless @sampled - return unless @started + StackProf.stop + log('Stopped') + end - StackProf.stop - log('Stopped') + def profile_context + { profile_id: @event_id } + end + + # Sets initial sampling decision of the profile. + # @return [void] + def set_initial_sample_decision(transaction_sampled) + unless Sentry.initialized? && Sentry.configuration.profiling_enabled? + @sampled = false + return end - def profile_context - { profile_id: @event_id } + unless transaction_sampled + @sampled = false + log('Discarding profile because transaction not sampled') + return end - # Sets initial sampling decision of the profile. - # @return [void] - def set_initial_sample_decision(transaction_sampled) - unless @profiling_enabled - @sampled = false - return - end + profiles_sample_rate = Sentry.configuration.profiles_sample_rate + + case profiles_sample_rate + when 0.0 + @sampled = false + log('Discarding profile because sample_rate is 0') + return + when 1.0 + @sampled = true + return + else + @sampled = Random.rand < profiles_sample_rate + end - unless transaction_sampled - @sampled = false - log('Discarding profile because transaction not sampled') - return - end + log('Discarding profile due to sampling decision') unless @sampled + end - if @profiles_sample_rate < 0.0 || @profiles_sample_rate > 1.0 - @sampled = false - log("Discarding profile because of invalid sample_rate: #{@profiles_sample_rate}") - return - end + def to_hash + return nil unless Sentry.initialized? + return nil unless @sampled + return nil unless @started - case @profiles_sample_rate - when 0.0 - @sampled = false - log('Discarding profile because sample_rate is 0') - return - when 1.0 - @sampled = true - return - else - @sampled = Random.rand < @profiles_sample_rate - end + results = StackProf.results + return nil unless results + return nil if results.empty? + return nil if results[:samples] == 0 + return nil unless results[:raw] - log('Discarding profile due to sampling decision') unless @sampled - end + frame_map = {} - def to_hash - return nil unless @sampled - return nil unless @started + frames = results[:frames].to_enum.with_index.map do |frame, idx| + frame_id, frame_data = frame - results = StackProf.results - return nil unless results - return nil if results.empty? + # need to map over stackprof frame ids to ours + frame_map[frame_id] = idx - frame_map = {} + in_app = in_app?(frame_data[:file]) + filename = compute_filename(frame_data[:file], in_app) + function, mod = split_module(frame_data[:name]) - frames = results[:frames].to_enum.with_index.map do |frame, idx| - frame_id, frame_data = frame + { + abs_path: frame_data[:file], + function: function, + module: mod, + lineno: frame_data[:line], + filename: filename, + in_app: in_app + }.compact + end - # need to map over stackprof frame ids to ours - frame_map[frame_id] = idx + idx = 0 + stacks = [] + num_seen = [] - in_app = in_app?(frame_data[:file]) - filename = compute_filename(frame_data[:file], in_app) - function, mod = split_module(frame_data[:name]) + # extract stacks from raw + # raw is a single array of [.., len_stack, *stack_frames(len_stack), num_stack_seen , ..] + while (len = results[:raw][idx]) + idx += 1 - { - abs_path: frame_data[:file], - function: function, - module: mod, - lineno: frame_data[:line], - filename: filename, - in_app: in_app - }.compact - end + # our call graph is reversed + stack = results[:raw].slice(idx, len).map { |id| frame_map[id] }.compact.reverse + stacks << stack - idx = 0 - stacks = [] - num_seen = [] + num_seen << results[:raw][idx + len] + idx += len + 1 - # extract stacks from raw - # raw is a single array of [.., len_stack, *stack_frames(len_stack), num_stack_seen , ..] - while (len = results[:raw][idx]) - idx += 1 + log('Unknown frame in stack') if stack.size != len + end - # our call graph is reversed - stack = results[:raw].slice(idx, len).map { |id| frame_map[id] }.compact.reverse - stacks << stack + idx = 0 + elapsed_since_start_ns = 0 + samples = [] - num_seen << results[:raw][idx + len] - idx += len + 1 + num_seen.each_with_index do |n, i| + n.times do + # stackprof deltas are in microseconds + delta = results[:raw_timestamp_deltas][idx] + elapsed_since_start_ns += (delta * 1e3).to_i + idx += 1 - log('Unknown frame in stack') if stack.size != len + # Not sure why but some deltas are very small like 0/1 values, + # they pollute our flamegraph so just ignore them for now. + # Open issue at https://github.com/tmm1/stackprof/issues/201 + next if delta < 10 + + samples << { + stack_id: i, + # TODO-neel-profiler we need to patch rb_profile_frames and write our own C extension to enable threading info. + # Till then, on multi-threaded servers like puma, we will get frames from other active threads when the one + # we're profiling is idle/sleeping/waiting for IO etc. + # https://bugs.ruby-lang.org/issues/10602 + thread_id: '0', + elapsed_since_start_ns: elapsed_since_start_ns.to_s + } end + end - idx = 0 - elapsed_since_start_ns = 0 - samples = [] - - num_seen.each_with_index do |n, i| - n.times do - # stackprof deltas are in microseconds - delta = results[:raw_timestamp_deltas][idx] - elapsed_since_start_ns += (delta * 1e3).to_i - idx += 1 - - # Not sure why but some deltas are very small like 0/1 values, - # they pollute our flamegraph so just ignore them for now. - # Open issue at https://github.com/tmm1/stackprof/issues/201 - next if delta < 10 - - samples << { - stack_id: i, - # TODO-neel-profiler we need to patch rb_profile_frames and write our own C extension to enable threading info. - # Till then, on multi-threaded servers like puma, we will get frames from other active threads when the one - # we're profiling is idle/sleeping/waiting for IO etc. - # https://bugs.ruby-lang.org/issues/10602 - thread_id: '0', - elapsed_since_start_ns: elapsed_since_start_ns.to_s - } - end - end + log('Some samples thrown away') if samples.size != results[:samples] - log('Some samples thrown away') if samples.size != results[:samples] + if samples.size <= 2 + log('Not enough samples, discarding profiler') + return nil + end - if samples.size <= 2 - log('Not enough samples, discarding profiler') - return nil - end + profile = { + frames: frames, + stacks: stacks, + samples: samples + } + + { + event_id: @event_id, + platform: PLATFORM, + version: VERSION, + profile: profile + } + end - profile = { - frames: frames, - stacks: stacks, - samples: samples - } + private - { - event_id: @event_id, - platform: PLATFORM, - version: VERSION, - profile: profile - } - end + def log(message) + Sentry.logger.debug(LOGGER_PROGNAME) { "[Profiler] #{message}" } + end - private + def project_root + @project_root ||= Sentry.configuration.project_root + end - def log(message) - Sentry.logger.debug(LOGGER_PROGNAME) { "[Profiler] #{message}" } + def in_app_pattern + @in_app_pattern ||= begin + app_dirs_pattern = Sentry.configuration.app_dirs_pattern || Backtrace::APP_DIRS_PATTERN + Regexp.new("^(#{project_root}/)?#{app_dirs_pattern}") end + end - def in_app?(abs_path) - abs_path.match?(@in_app_pattern) - end + def in_app?(abs_path) + abs_path.match?(in_app_pattern) + end - # copied from stacktrace.rb since I don't want to touch existing code - # TODO-neel-profiler try to fetch this from stackprof once we patch - # the native extension - def compute_filename(abs_path, in_app) - return nil if abs_path.nil? + # copied from stacktrace.rb since I don't want to touch existing code + # TODO-neel-profiler try to fetch this from stackprof once we patch + # the native extension + def compute_filename(abs_path, in_app) + return nil if abs_path.nil? - under_project_root = @project_root && abs_path.start_with?(@project_root) + under_project_root = project_root && abs_path.start_with?(project_root) - prefix = - if under_project_root && in_app - @project_root - else - longest_load_path = $LOAD_PATH.select { |path| abs_path.start_with?(path.to_s) }.max_by(&:size) + prefix = + if under_project_root && in_app + project_root + else + longest_load_path = $LOAD_PATH.select { |path| abs_path.start_with?(path.to_s) }.max_by(&:size) - if under_project_root - longest_load_path || @project_root - else - longest_load_path - end + if under_project_root + longest_load_path || project_root + else + longest_load_path end + end - prefix ? abs_path[prefix.to_s.chomp(File::SEPARATOR).length + 1..-1] : abs_path - end + prefix ? abs_path[prefix.to_s.chomp(File::SEPARATOR).length + 1..-1] : abs_path + end - def split_module(name) - # last module plus class/instance method - i = name.rindex('::') - function = i ? name[(i + 2)..-1] : name - mod = i ? name[0...i] : nil + def split_module(name) + # last module plus class/instance method + i = name.rindex('::') + function = i ? name[(i + 2)..-1] : name + mod = i ? name[0...i] : nil - [function, mod] - end + [function, mod] end end end diff --git a/sentry-ruby/lib/sentry/transport.rb b/sentry-ruby/lib/sentry/transport.rb index 2c217ab87..cdfc23359 100644 --- a/sentry-ruby/lib/sentry/transport.rb +++ b/sentry-ruby/lib/sentry/transport.rb @@ -61,7 +61,6 @@ def send_envelope(envelope) if data log_info("[Transport] Sending envelope with items [#{serialized_items.map(&:type).join(', ')}] #{envelope.event_id} to Sentry") - File.open('/tmp/dump', 'w') { |file| file.write(data) } if envelope.items.map(&:type).include?('profile') send_data(data) end end diff --git a/sentry-ruby/spec/sentry/configuration_spec.rb b/sentry-ruby/spec/sentry/configuration_spec.rb index 37ccf508b..d36284057 100644 --- a/sentry-ruby/spec/sentry/configuration_spec.rb +++ b/sentry-ruby/spec/sentry/configuration_spec.rb @@ -154,6 +154,40 @@ end end + describe "#profiling_enabled?" do + it "returns false unless tracing enabled" do + subject.enable_tracing = false + expect(subject.profiling_enabled?).to eq(false) + end + + it "returns false unless sending enabled" do + subject.enable_tracing = true + subject.profiles_sample_rate = 1.0 + allow(subject).to receive(:sending_allowed?).and_return(false) + expect(subject.profiling_enabled?).to eq(false) + end + + context 'when tracing and sending enabled' do + before { subject.enable_tracing = true } + before { allow(subject).to receive(:sending_allowed?).and_return(true) } + + it "returns false if nil sample rate" do + subject.profiles_sample_rate = nil + expect(subject.profiling_enabled?).to eq(false) + end + + it "returns false if invalid sample rate" do + subject.profiles_sample_rate = 5.0 + expect(subject.profiling_enabled?).to eq(false) + end + + it "returns true if valid sample rate" do + subject.profiles_sample_rate = 0.5 + expect(subject.profiling_enabled?).to eq(true) + end + end + end + describe "#enable_tracing=" do it "sets traces_sample_rate to 1.0 automatically" do subject.enable_tracing = true diff --git a/sentry-ruby/spec/sentry/profiler_spec.rb b/sentry-ruby/spec/sentry/profiler_spec.rb new file mode 100644 index 000000000..b0bbb033b --- /dev/null +++ b/sentry-ruby/spec/sentry/profiler_spec.rb @@ -0,0 +1,262 @@ +require "spec_helper" + +return unless defined?(Sentry::Profiler) + +RSpec.describe Sentry::Profiler do + before do + perform_basic_setup do |config| + config.traces_sample_rate = 1.0 + config.profiles_sample_rate = 1.0 + end + end + + before { StackProf.stop } + + describe '#start' do + context 'without sampling decision' do + it 'does not start StackProf' do + expect(StackProf).not_to receive(:start) + subject.start + expect(subject.started).to eq(false) + end + end + + context 'with sampling decision' do + it 'does not start StackProf if not sampled' do + subject.set_initial_sample_decision(false) + expect(StackProf).not_to receive(:start) + subject.start + expect(subject.started).to eq(false) + end + + it 'starts StackProf if sampled' do + subject.set_initial_sample_decision(true) + + expect(StackProf).to receive(:start).with( + interval: 1e6 / 101, + mode: :wall, + raw: true, + aggregate: false + ).and_call_original + + subject.start + expect(subject.started).to eq(true) + end + + it 'does not start StackProf again if already started' do + StackProf.start + subject.set_initial_sample_decision(true) + expect(StackProf).to receive(:start).and_call_original + + subject.start + expect(subject.started).to eq(false) + end + end + end + + describe '#stop' do + it 'does not stop StackProf if not sampled' do + subject.set_initial_sample_decision(false) + expect(StackProf).not_to receive(:stop) + subject.stop + end + + it 'does not stop StackProf if sampled but not started' do + subject.set_initial_sample_decision(true) + expect(StackProf).not_to receive(:stop) + subject.stop + end + + it 'stops StackProf if sampled and started' do + subject.set_initial_sample_decision(true) + subject.start + expect(StackProf).to receive(:stop) + subject.stop + end + end + + describe '#profile_context' do + it 'returns profile context hash' do + expect(subject.profile_context).to eq({ profile_id: subject.event_id }) + end + end + + describe '#set_initial_sample_decision' do + context 'with profiling disabled' do + it 'does not sample when profiles_sample_rate is nil' do + Sentry.configuration.profiles_sample_rate = nil + + subject.set_initial_sample_decision(true) + expect(subject.sampled).to eq(false) + end + + it 'does not sample when profiles_sample_rate is invalid' do + Sentry.configuration.profiles_sample_rate = 5.0 + + subject.set_initial_sample_decision(true) + expect(subject.sampled).to eq(false) + end + end + + context 'with profiling enabled' do + it 'does not sample when parent transaction is not sampled' do + subject.set_initial_sample_decision(false) + expect(subject.sampled).to eq(false) + end + + it 'does not sample when profiles_sample_rate is 0' do + Sentry.configuration.profiles_sample_rate = 0 + + subject.set_initial_sample_decision(true) + expect(subject.sampled).to eq(false) + end + + it 'samples when profiles_sample_rate is 1' do + subject.set_initial_sample_decision(true) + expect(subject.sampled).to eq(true) + end + + it 'uses profiles_sample_rate for sampling (positive result)' do + Sentry.configuration.profiles_sample_rate = 0.5 + expect(Random).to receive(:rand).and_return(0.4) + subject.set_initial_sample_decision(true) + expect(subject.sampled).to eq(true) + end + + it 'uses profiles_sample_rate for sampling (negative result)' do + Sentry.configuration.profiles_sample_rate = 0.5 + expect(Random).to receive(:rand).and_return(0.6) + subject.set_initial_sample_decision(true) + expect(subject.sampled).to eq(false) + end + end + end + + describe '#to_hash' do + it 'returns nil unless sampled' do + subject.set_initial_sample_decision(false) + expect(subject.to_hash).to eq(nil) + end + + it 'returns nil unless started' do + subject.set_initial_sample_decision(true) + expect(subject.to_hash).to eq(nil) + end + + it 'returns nil if empty results' do + subject.set_initial_sample_decision(true) + subject.start + subject.stop + + expect(StackProf).to receive(:results).and_call_original + expect(subject.to_hash).to eq(nil) + end + + context 'with profiled code' do + # profiled with following code + # module Bar + # module Foo + # def self.foo + # 1e6.to_i.times { 2**2 } + # end + # end + + # def self.bar + # Foo.foo + # sleep 0.1 + # end + # end + # + # Bar.bar + let(:stackprof_results) do + data = StackProf::Report.from_file('spec/support/stackprof_results.json').data + # relative dir differs on each machine + data[:frames].each { |_id, fra| fra[:file].gsub!(//, Dir.pwd) } + data + end + + before do + allow(StackProf).to receive(:results).and_return(stackprof_results) + subject.set_initial_sample_decision(true) + subject.start + subject.stop + end + + it 'has correct attributes' do + hash = subject.to_hash + + expect(hash[:event_id]).to eq(subject.event_id) + expect(hash[:platform]).to eq('ruby') + expect(hash[:version]).to eq('1') + expect(hash[:profile]).to include(:frames, :stacks, :samples) + end + + it 'has correct frames' do + frames = subject.to_hash[:profile][:frames] + + foo_frame = frames.find { |f| f[:function] =~ /foo/ } + expect(foo_frame[:function]).to eq('Foo.foo') + expect(foo_frame[:module]).to eq('Bar') + expect(foo_frame[:in_app]).to eq(true) + expect(foo_frame[:lineno]).to eq(7) + expect(foo_frame[:filename]).to eq('spec/sentry/profiler_spec.rb') + expect(foo_frame[:abs_path]).to include('sentry-ruby/sentry-ruby/spec/sentry/profiler_spec.rb') + + bar_frame = frames.find { |f| f[:function] =~ /bar/ } + expect(bar_frame[:function]).to eq('Bar.bar') + expect(bar_frame[:module]).to eq(nil) + expect(bar_frame[:in_app]).to eq(true) + expect(bar_frame[:lineno]).to eq(12) + expect(bar_frame[:filename]).to eq('spec/sentry/profiler_spec.rb') + expect(bar_frame[:abs_path]).to include('sentry-ruby/sentry-ruby/spec/sentry/profiler_spec.rb') + + sleep_frame = frames.find { |f| f[:function] =~ /sleep/ } + expect(sleep_frame[:function]).to eq('Kernel#sleep') + expect(sleep_frame[:module]).to eq(nil) + expect(sleep_frame[:in_app]).to eq(false) + expect(sleep_frame[:lineno]).to eq(nil) + expect(sleep_frame[:filename]).to eq('') + expect(sleep_frame[:abs_path]).to include('') + + times_frame = frames.find { |f| f[:function] =~ /times/ } + expect(times_frame[:function]).to eq('Integer#times') + expect(times_frame[:module]).to eq(nil) + expect(times_frame[:in_app]).to eq(false) + expect(times_frame[:lineno]).to eq(nil) + expect(times_frame[:filename]).to eq('') + expect(times_frame[:abs_path]).to include('') + end + + it 'has correct stacks' do + profile = subject.to_hash[:profile] + frames = profile[:frames] + stacks = profile[:stacks] + + # look at tops, rest is ruby/rspec stuff + stack_tops = stacks.map { |s| s.take(3) }.map { |s| s.map { |i| frames[i][:function] } } + expect(stack_tops).to include(['Foo.foo', 'Integer#times', 'Foo.foo']) + expect(stack_tops).to include(['Integer#times', 'Foo.foo', 'Bar.bar']) + + stack_tops2 = stack_tops.map { |s| s.take(2) } + expect(stack_tops2).to include(['Kernel#sleep', 'Bar.bar']) + end + + it 'has correct samples' do + profile = subject.to_hash[:profile] + num_stacks = profile[:stacks].size + samples = profile[:samples] + last_elapsed = 0 + + samples.each do |sample| + expect(sample[:thread_id]).to eq('0') + expect(sample[:stack_id]).to be_between(0, num_stacks - 1) + + expect(sample[:elapsed_since_start_ns]).to be_a(String) + elapsed = sample[:elapsed_since_start_ns].to_i + expect(elapsed).to be > last_elapsed + last_elapsed = elapsed + end + end + end + end +end diff --git a/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb b/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb index 68c5ee167..e2ab2d208 100644 --- a/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb +++ b/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb @@ -1,7 +1,14 @@ -return unless defined?(Rack) +# return unless defined?(Rack) require 'spec_helper' +module TestApp + def self.foo + sleep 0.1 + "ok" + end +end + RSpec.describe Sentry::Rack::CaptureExceptions, rack: true do let(:exception) { ZeroDivisionError.new("divided by 0") } let(:additional_headers) { {} } @@ -640,4 +647,63 @@ def will_be_sampled_by_sdk end end end + + describe "profiling" do + context "when profiling is enabled" do + before do + perform_basic_setup do |config| + config.traces_sample_rate = 1.0 + config.profiles_sample_rate = 1.0 + config.release = "test-release" + end + end + + it "collects a profile" do + app = ->(_) do + [200, {}, [TestApp.foo]] + end + + stack = described_class.new(app) + stack.call(env) + event = last_sentry_event + + profile = event.profile + expect(profile).not_to be_nil + + expect(profile[:event_id]).not_to be_nil + expect(event.contexts[:profile]).to eq({ profile_id: profile[:event_id] }) + + expect(profile[:platform]).to eq("ruby") + expect(profile[:version]).to eq("1") + expect(profile[:environment]).to eq("development") + expect(profile[:release]).to eq("test-release") + expect { Time.parse(profile[:timestamp]) }.not_to raise_error + + expect(profile[:device]).to include(:architecture) + expect(profile[:os]).to include(:name, :version) + expect(profile[:runtime]).to include(:name, :version) + + expect(profile[:transaction]).to include(:id, :name, :trace_id, :active_thead_id) + expect(profile[:transaction][:id]).to eq(event.event_id) + expect(profile[:transaction][:name]).to eq(event.transaction) + expect(profile[:transaction][:trace_id]).to eq(event.contexts[:trace][:trace_id]) + expect(profile[:transaction][:active_thead_id]).to eq("0") + + # detailed checking of content is done in profiler_spec, + # just check basic structure here + frames = profile[:profile][:frames] + expect(frames).to be_a(Array) + expect(frames.first).to include(:function, :filename, :abs_path, :in_app) + + stacks = profile[:profile][:stacks] + expect(stacks).to be_a(Array) + expect(stacks.first).to be_a(Array) + expect(stacks.first.first).to be_a(Integer) + + samples = profile[:profile][:samples] + expect(samples).to be_a(Array) + expect(samples.first).to include(:stack_id, :thread_id, :elapsed_since_start_ns) + end + end + end end diff --git a/sentry-ruby/spec/sentry/transport_spec.rb b/sentry-ruby/spec/sentry/transport_spec.rb index a1c5f885b..eee584623 100644 --- a/sentry-ruby/spec/sentry/transport_spec.rb +++ b/sentry-ruby/spec/sentry/transport_spec.rb @@ -84,6 +84,60 @@ expect(item).to eq(event.to_hash.to_json) end + + context "with profiling on transaction" do + let(:profile) do + frames = [ + { function: "foo" }, + { function: "bar" }, + { function: "baz" } + ] + + stacks = [ + [0, 1], + [0, 2], + [1, 2], + [0, 1, 2] + ] + + samples = [ + { stack_id: 0, elapsed_since_start_ns: 10000 }, + { stack_id: 0, elapsed_since_start_ns: 20000 }, + { stack_id: 1, elapsed_since_start_ns: 30000 }, + { stack_id: 2, elapsed_since_start_ns: 40000 }, + { stack_id: 3, elapsed_since_start_ns: 50000 } + ] + + { + environment: "test", + release: "release", + profile: { + frames: frames, + stacks: stacks, + samples: samples + } + } + end + + let(:event_with_profile) do + event.profile = profile + event + end + + let(:envelope) { subject.envelope_from_event(event_with_profile) } + + it "adds profile item to envelope" do + result, _ = subject.serialize_envelope(envelope) + + profile_header, profile_payload = result.split("\n").last(2) + + expect(profile_header).to eq( + '{"type":"profile","content_type":"application/json"}' + ) + + expect(profile_payload).to eq(profile.to_json) + end + end end context "client report" do diff --git a/sentry-ruby/spec/spec_helper.rb b/sentry-ruby/spec/spec_helper.rb index c38e35399..77485b550 100644 --- a/sentry-ruby/spec/spec_helper.rb +++ b/sentry-ruby/spec/spec_helper.rb @@ -5,6 +5,7 @@ require "simplecov" require "rspec/retry" require "redis" +require "stackprof" unless RUBY_PLATFORM == "java" SimpleCov.start do project_name "sentry-ruby" diff --git a/sentry-ruby/spec/support/stackprof_results.json b/sentry-ruby/spec/support/stackprof_results.json new file mode 100644 index 000000000..1527df8cd --- /dev/null +++ b/sentry-ruby/spec/support/stackprof_results.json @@ -0,0 +1 @@ +{"version":1.2,"mode":"wall","interval":9900.990099009901,"samples":15,"gc_samples":0,"missed_samples":0,"metadata":{},"frames":{"140370219074600":{"name":"Integer#times","file":"","line":null,"total_samples":5,"samples":2},"140370222379560":{"name":"Bar::Foo.foo","file":"/spec/sentry/profiler_spec.rb","line":7,"total_samples":5,"samples":2},"140370222379480":{"name":"Bar.bar","file":"/spec/sentry/profiler_spec.rb","line":12,"total_samples":15,"samples":0},"140370262463760":{"name":"block (4 levels) in ","file":"/spec/sentry/profiler_spec.rb","line":169,"total_samples":15,"samples":0},"140370219081000":{"name":"BasicObject#instance_exec","file":"","line":null,"total_samples":15,"samples":0},"140369934628760":{"name":"RSpec::Core::Example#instance_exec","file":"/Users/neel/.rvm/gems/ruby-3.0.0/gems/rspec-core-3.11.0/lib/rspec/core/example.rb","line":456,"total_samples":15,"samples":0},"140370262209000":{"name":"RSpec::Core::Hooks::BeforeHook#run","file":"/Users/neel/.rvm/gems/ruby-3.0.0/gems/rspec-core-3.11.0/lib/rspec/core/hooks.rb","line":364,"total_samples":15,"samples":0},"140370262206960":{"name":"RSpec::Core::Hooks::HookCollections#run_owned_hooks_for","file":"/Users/neel/.rvm/gems/ruby-3.0.0/gems/rspec-core-3.11.0/lib/rspec/core/hooks.rb","line":527,"total_samples":15,"samples":0},"140370219016480":{"name":"Array#each","file":"","line":null,"total_samples":15,"samples":0},"140370262206440":{"name":"RSpec::Core::Hooks::HookCollections#run_example_hooks_for","file":"/Users/neel/.rvm/gems/ruby-3.0.0/gems/rspec-core-3.11.0/lib/rspec/core/hooks.rb","line":613,"total_samples":15,"samples":0},"140370219016360":{"name":"Array#reverse_each","file":"","line":null,"total_samples":15,"samples":0},"140370262207720":{"name":"RSpec::Core::Hooks::HookCollections#run","file":"/Users/neel/.rvm/gems/ruby-3.0.0/gems/rspec-core-3.11.0/lib/rspec/core/hooks.rb","line":475,"total_samples":15,"samples":0},"140369934628120":{"name":"RSpec::Core::Example#run_before_example","file":"/Users/neel/.rvm/gems/ruby-3.0.0/gems/rspec-core-3.11.0/lib/rspec/core/example.rb","line":503,"total_samples":15,"samples":0},"140369934656240":{"name":"RSpec::Core::Example#run","file":"/Users/neel/.rvm/gems/ruby-3.0.0/gems/rspec-core-3.11.0/lib/rspec/core/example.rb","line":246,"total_samples":15,"samples":0},"140369934628080":{"name":"RSpec::Core::Example#with_around_and_singleton_context_hooks","file":"/Users/neel/.rvm/gems/ruby-3.0.0/gems/rspec-core-3.11.0/lib/rspec/core/example.rb","line":508,"total_samples":15,"samples":0},"140369934628640":{"name":"RSpec::Core::Example#with_around_example_hooks","file":"/Users/neel/.rvm/gems/ruby-3.0.0/gems/rspec-core-3.11.0/lib/rspec/core/example.rb","line":466,"total_samples":15,"samples":0},"140370262206400":{"name":"RSpec::Core::Hooks::HookCollections#run_around_example_hooks_for","file":"/Users/neel/.rvm/gems/ruby-3.0.0/gems/rspec-core-3.11.0/lib/rspec/core/hooks.rb","line":619,"total_samples":15,"samples":0},"140369934629600":{"name":"RSpec::Core::Example::Procsy#call","file":"/Users/neel/.rvm/gems/ruby-3.0.0/gems/rspec-core-3.11.0/lib/rspec/core/example.rb","line":350,"total_samples":15,"samples":0},"140369936132760":{"name":"RSpec::Retry#run","file":"/Users/neel/.rvm/gems/ruby-3.0.0/gems/rspec-retry-0.6.2/lib/rspec/retry.rb","line":107,"total_samples":15,"samples":0},"140370203515000":{"name":"Kernel#loop","file":"","line":null,"total_samples":15,"samples":0},"140369936134000":{"name":"RSpec::Core::Example::Procsy#run_with_retry","file":"/Users/neel/.rvm/gems/ruby-3.0.0/gems/rspec-retry-0.6.2/lib/rspec_ext/rspec_ext.rb","line":11,"total_samples":15,"samples":0},"140369936133560":{"name":"RSpec::Retry.setup","file":"/Users/neel/.rvm/gems/ruby-3.0.0/gems/rspec-retry-0.6.2/lib/rspec/retry.rb","line":7,"total_samples":15,"samples":0},"140370262208320":{"name":"RSpec::Core::Hooks::AroundHook#execute_with","file":"/Users/neel/.rvm/gems/ruby-3.0.0/gems/rspec-core-3.11.0/lib/rspec/core/hooks.rb","line":389,"total_samples":15,"samples":0},"140369934629640":{"name":"RSpec::Core::Example::Procsy#call","file":"/Users/neel/.rvm/gems/ruby-3.0.0/gems/rspec-core-3.11.0/lib/rspec/core/example.rb","line":350,"total_samples":15,"samples":0},"140370221599800":{"name":"RSpec::Core::ExampleGroup.run_examples","file":"/Users/neel/.rvm/gems/ruby-3.0.0/gems/rspec-core-3.11.0/lib/rspec/core/example_group.rb","line":641,"total_samples":15,"samples":0},"140370219015440":{"name":"Array#map","file":"","line":null,"total_samples":15,"samples":0},"140370221599880":{"name":"RSpec::Core::ExampleGroup.run","file":"/Users/neel/.rvm/gems/ruby-3.0.0/gems/rspec-core-3.11.0/lib/rspec/core/example_group.rb","line":599,"total_samples":15,"samples":0},"140369934821040":{"name":"RSpec::Core::Runner#run_specs","file":"/Users/neel/.rvm/gems/ruby-3.0.0/gems/rspec-core-3.11.0/lib/rspec/core/runner.rb","line":113,"total_samples":15,"samples":0},"140370221475080":{"name":"RSpec::Core::Configuration#with_suite_hooks","file":"/Users/neel/.rvm/gems/ruby-3.0.0/gems/rspec-core-3.11.0/lib/rspec/core/configuration.rb","line":2062,"total_samples":15,"samples":0},"140370262307680":{"name":"RSpec::Core::Reporter#report","file":"/Users/neel/.rvm/gems/ruby-3.0.0/gems/rspec-core-3.11.0/lib/rspec/core/reporter.rb","line":71,"total_samples":15,"samples":0},"140369934821120":{"name":"RSpec::Core::Runner#run","file":"/Users/neel/.rvm/gems/ruby-3.0.0/gems/rspec-core-3.11.0/lib/rspec/core/runner.rb","line":85,"total_samples":15,"samples":0},"140369934821200":{"name":"RSpec::Core::Runner.run","file":"/Users/neel/.rvm/gems/ruby-3.0.0/gems/rspec-core-3.11.0/lib/rspec/core/runner.rb","line":64,"total_samples":15,"samples":0},"140369934821320":{"name":"RSpec::Core::Runner.invoke","file":"/Users/neel/.rvm/gems/ruby-3.0.0/gems/rspec-core-3.11.0/lib/rspec/core/runner.rb","line":43,"total_samples":15,"samples":0},"140369934947600":{"name":"","file":"/Users/neel/.rvm/gems/ruby-3.0.0/gems/rspec-core-3.11.0/exe/rspec","total_samples":15,"samples":0},"140370220922120":{"name":"Kernel#load","file":"","line":null,"total_samples":15,"samples":0},"140369934788840":{"name":"
","file":"/Users/neel/.rvm/gems/ruby-3.0.0/bin/rspec","line":1,"total_samples":15,"samples":0},"140370219331600":{"name":"Kernel#eval","file":"","line":null,"total_samples":15,"samples":0},"140369933326520":{"name":"
","file":"/Users/neel/.rvm/gems/ruby-3.0.0/bin/ruby_executable_hooks","total_samples":15,"samples":0},"140370218844600":{"name":"
","file":"/Users/neel/.rvm/gems/ruby-3.0.0/bin/ruby_executable_hooks","total_samples":15,"samples":0},"140370219073720":{"name":"Integer#**","file":"","line":null,"total_samples":1,"samples":1},"140370265410040":{"name":"Kernel#sleep","file":"","line":null,"total_samples":10,"samples":10}},"raw":[62,140370218844600,140369933326520,140370219331600,140369934788840,140370220922120,140369934947600,140369934821320,140369934821200,140369934821120,140369934821040,140370262307680,140369934821040,140370221475080,140369934821040,140370219015440,140369934821040,140370221599880,140370219015440,140370221599880,140370221599880,140370219015440,140370221599880,140370221599880,140370221599800,140370219015440,140370221599800,140369934656240,140369934628080,140369934628640,140370262207720,140370262206400,140369934629640,140370262206400,140370262208320,140369934628760,140370219081000,140369936133560,140369936134000,140369936132760,140370203515000,140369936132760,140369934629600,140370262206400,140370262207720,140369934628640,140369934628080,140369934656240,140369934628120,140370262207720,140370262206440,140370219016360,140370262206440,140370262206960,140370219016480,140370262206960,140370262209000,140369934628760,140370219081000,140370262463760,140370222379480,140370222379560,140370219074600,1,63,140370218844600,140369933326520,140370219331600,140369934788840,140370220922120,140369934947600,140369934821320,140369934821200,140369934821120,140369934821040,140370262307680,140369934821040,140370221475080,140369934821040,140370219015440,140369934821040,140370221599880,140370219015440,140370221599880,140370221599880,140370219015440,140370221599880,140370221599880,140370221599800,140370219015440,140370221599800,140369934656240,140369934628080,140369934628640,140370262207720,140370262206400,140369934629640,140370262206400,140370262208320,140369934628760,140370219081000,140369936133560,140369936134000,140369936132760,140370203515000,140369936132760,140369934629600,140370262206400,140370262207720,140369934628640,140369934628080,140369934656240,140369934628120,140370262207720,140370262206440,140370219016360,140370262206440,140370262206960,140370219016480,140370262206960,140370262209000,140369934628760,140370219081000,140370262463760,140370222379480,140370222379560,140370219074600,140370222379560,1,62,140370218844600,140369933326520,140370219331600,140369934788840,140370220922120,140369934947600,140369934821320,140369934821200,140369934821120,140369934821040,140370262307680,140369934821040,140370221475080,140369934821040,140370219015440,140369934821040,140370221599880,140370219015440,140370221599880,140370221599880,140370219015440,140370221599880,140370221599880,140370221599800,140370219015440,140370221599800,140369934656240,140369934628080,140369934628640,140370262207720,140370262206400,140369934629640,140370262206400,140370262208320,140369934628760,140370219081000,140369936133560,140369936134000,140369936132760,140370203515000,140369936132760,140369934629600,140370262206400,140370262207720,140369934628640,140369934628080,140369934656240,140369934628120,140370262207720,140370262206440,140370219016360,140370262206440,140370262206960,140370219016480,140370262206960,140370262209000,140369934628760,140370219081000,140370262463760,140370222379480,140370222379560,140370219074600,1,64,140370218844600,140369933326520,140370219331600,140369934788840,140370220922120,140369934947600,140369934821320,140369934821200,140369934821120,140369934821040,140370262307680,140369934821040,140370221475080,140369934821040,140370219015440,140369934821040,140370221599880,140370219015440,140370221599880,140370221599880,140370219015440,140370221599880,140370221599880,140370221599800,140370219015440,140370221599800,140369934656240,140369934628080,140369934628640,140370262207720,140370262206400,140369934629640,140370262206400,140370262208320,140369934628760,140370219081000,140369936133560,140369936134000,140369936132760,140370203515000,140369936132760,140369934629600,140370262206400,140370262207720,140369934628640,140369934628080,140369934656240,140369934628120,140370262207720,140370262206440,140370219016360,140370262206440,140370262206960,140370219016480,140370262206960,140370262209000,140369934628760,140370219081000,140370262463760,140370222379480,140370222379560,140370219074600,140370222379560,140370219073720,1,63,140370218844600,140369933326520,140370219331600,140369934788840,140370220922120,140369934947600,140369934821320,140369934821200,140369934821120,140369934821040,140370262307680,140369934821040,140370221475080,140369934821040,140370219015440,140369934821040,140370221599880,140370219015440,140370221599880,140370221599880,140370219015440,140370221599880,140370221599880,140370221599800,140370219015440,140370221599800,140369934656240,140369934628080,140369934628640,140370262207720,140370262206400,140369934629640,140370262206400,140370262208320,140369934628760,140370219081000,140369936133560,140369936134000,140369936132760,140370203515000,140369936132760,140369934629600,140370262206400,140370262207720,140369934628640,140369934628080,140369934656240,140369934628120,140370262207720,140370262206440,140370219016360,140370262206440,140370262206960,140370219016480,140370262206960,140370262209000,140369934628760,140370219081000,140370262463760,140370222379480,140370222379560,140370219074600,140370222379560,1,61,140370218844600,140369933326520,140370219331600,140369934788840,140370220922120,140369934947600,140369934821320,140369934821200,140369934821120,140369934821040,140370262307680,140369934821040,140370221475080,140369934821040,140370219015440,140369934821040,140370221599880,140370219015440,140370221599880,140370221599880,140370219015440,140370221599880,140370221599880,140370221599800,140370219015440,140370221599800,140369934656240,140369934628080,140369934628640,140370262207720,140370262206400,140369934629640,140370262206400,140370262208320,140369934628760,140370219081000,140369936133560,140369936134000,140369936132760,140370203515000,140369936132760,140369934629600,140370262206400,140370262207720,140369934628640,140369934628080,140369934656240,140369934628120,140370262207720,140370262206440,140370219016360,140370262206440,140370262206960,140370219016480,140370262206960,140370262209000,140369934628760,140370219081000,140370262463760,140370222379480,140370265410040,10],"raw_sample_timestamps":[1295905330989,1295905338595,1295905348330,1295905358336,1295905368777,1295905379129,1295905388495,1295905398492,1295905407835,1295905418826,1295905428669,1295905438609,1295905447579,1295905458008,1295905468407],"raw_timestamp_deltas":[12403,7531,9689,9986,10420,10338,9320,9949,9269,10920,9770,9864,8899,10354,10323]} From f44a6ef40c1510d2fed2420d753ef407e7307f10 Mon Sep 17 00:00:00 2001 From: Neel Shah Date: Tue, 11 Apr 2023 15:50:47 +0200 Subject: [PATCH 08/18] TestHelper spec needs to require spec_helper for other setup --- sentry-ruby/spec/sentry/test_helper_spec.rb | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/sentry-ruby/spec/sentry/test_helper_spec.rb b/sentry-ruby/spec/sentry/test_helper_spec.rb index b6448ba38..fd3b1d1a6 100644 --- a/sentry-ruby/spec/sentry/test_helper_spec.rb +++ b/sentry-ruby/spec/sentry/test_helper_spec.rb @@ -1,5 +1,4 @@ -require "sentry-ruby" -require "sentry/test_helper" +require "spec_helper" RSpec.describe Sentry::TestHelper do include described_class From 0eab2476957ee4cdd642339a147f3b9ad41f187e Mon Sep 17 00:00:00 2001 From: Neel Shah Date: Tue, 11 Apr 2023 16:14:08 +0200 Subject: [PATCH 09/18] Review fixes --- sentry-ruby/lib/sentry/configuration.rb | 9 +--- sentry-ruby/lib/sentry/hub.rb | 6 +-- sentry-ruby/lib/sentry/profiler.rb | 57 +++++++++++------------- sentry-ruby/lib/sentry/transaction.rb | 13 +++++- sentry-ruby/spec/sentry/profiler_spec.rb | 2 + 5 files changed, 42 insertions(+), 45 deletions(-) diff --git a/sentry-ruby/lib/sentry/configuration.rb b/sentry-ruby/lib/sentry/configuration.rb index 2f919aa76..55adf928b 100644 --- a/sentry-ruby/lib/sentry/configuration.rb +++ b/sentry-ruby/lib/sentry/configuration.rb @@ -402,14 +402,7 @@ def enable_tracing=(enable_tracing) end def profiles_sample_rate=(profiles_sample_rate) - log_info("Thank you for trying out Profiling on Sentry. Please note that this is currently an experimental feature.") - - if defined?(StackProf) - log_info("Feedback on how it is working for you is appreciated!") - else - log_info("Please make sure to include the 'stackprof' gem in your Gemfile to use Profiling with Sentry.") - end - + log_info("Please make sure to include the 'stackprof' gem in your Gemfile to use Profiling with Sentry.") unless defined?(StackProf) @profiles_sample_rate = profiles_sample_rate end diff --git a/sentry-ruby/lib/sentry/hub.rb b/sentry-ruby/lib/sentry/hub.rb index 98811fc8b..92cc2ed6b 100644 --- a/sentry-ruby/lib/sentry/hub.rb +++ b/sentry-ruby/lib/sentry/hub.rb @@ -88,13 +88,9 @@ def start_transaction(transaction: nil, custom_sampling_context: {}, instrumente } sampling_context.merge!(custom_sampling_context) - transaction.set_initial_sample_decision(sampling_context: sampling_context) - if transaction.profiler - transaction.profiler.set_initial_sample_decision(transaction.sampled) - transaction.profiler.start - end + transaction.start_profiler! transaction end diff --git a/sentry-ruby/lib/sentry/profiler.rb b/sentry-ruby/lib/sentry/profiler.rb index df5276904..31534d29e 100644 --- a/sentry-ruby/lib/sentry/profiler.rb +++ b/sentry-ruby/lib/sentry/profiler.rb @@ -11,13 +11,20 @@ class Profiler PLATFORM = 'ruby' # 101 Hz in microseconds DEFAULT_INTERVAL = 1e6 / 101 + MICRO_TO_NANO_SECONDS = 1e3 attr_reader :sampled, :started, :event_id - def initialize + def initialize(configuration) @event_id = SecureRandom.uuid.delete('-') @started = false @sampled = nil + + @profiling_enabled = configuration.profiling_enabled? + @profiles_sample_rate = configuration.profiles_sample_rate + @project_root = configuration.project_root + @app_dirs_pattern = configuration.app_dirs_pattern || Backtrace::APP_DIRS_PATTERN + @in_app_pattern = Regexp.new("^(#{@project_root}/)?#{@app_dirs_pattern}") end def start @@ -46,7 +53,7 @@ def profile_context # Sets initial sampling decision of the profile. # @return [void] def set_initial_sample_decision(transaction_sampled) - unless Sentry.initialized? && Sentry.configuration.profiling_enabled? + unless @profiling_enabled @sampled = false return end @@ -57,9 +64,7 @@ def set_initial_sample_decision(transaction_sampled) return end - profiles_sample_rate = Sentry.configuration.profiles_sample_rate - - case profiles_sample_rate + case @profiles_sample_rate when 0.0 @sampled = false log('Discarding profile because sample_rate is 0') @@ -68,14 +73,13 @@ def set_initial_sample_decision(transaction_sampled) @sampled = true return else - @sampled = Random.rand < profiles_sample_rate + @sampled = Random.rand < @profiles_sample_rate end log('Discarding profile due to sampling decision') unless @sampled end def to_hash - return nil unless Sentry.initialized? return nil unless @sampled return nil unless @started @@ -93,18 +97,22 @@ def to_hash # need to map over stackprof frame ids to ours frame_map[frame_id] = idx - in_app = in_app?(frame_data[:file]) - filename = compute_filename(frame_data[:file], in_app) + file_path = frame_data[:file] + in_app = in_app?(file_path) + filename = compute_filename(file_path, in_app) function, mod = split_module(frame_data[:name]) - { - abs_path: frame_data[:file], + frame_hash = { + abs_path: file_path, function: function, - module: mod, - lineno: frame_data[:line], filename: filename, in_app: in_app - }.compact + } + + frame_hash[:module] = mod if mod + frame_hash[:lineno] = frame_data[:line] if frame_data[:line] + + frame_hash end idx = 0 @@ -134,7 +142,7 @@ def to_hash n.times do # stackprof deltas are in microseconds delta = results[:raw_timestamp_deltas][idx] - elapsed_since_start_ns += (delta * 1e3).to_i + elapsed_since_start_ns += (delta * MICRO_TO_NANO_SECONDS).to_i idx += 1 # Not sure why but some deltas are very small like 0/1 values, @@ -181,19 +189,8 @@ def log(message) Sentry.logger.debug(LOGGER_PROGNAME) { "[Profiler] #{message}" } end - def project_root - @project_root ||= Sentry.configuration.project_root - end - - def in_app_pattern - @in_app_pattern ||= begin - app_dirs_pattern = Sentry.configuration.app_dirs_pattern || Backtrace::APP_DIRS_PATTERN - Regexp.new("^(#{project_root}/)?#{app_dirs_pattern}") - end - end - def in_app?(abs_path) - abs_path.match?(in_app_pattern) + abs_path.match?(@in_app_pattern) end # copied from stacktrace.rb since I don't want to touch existing code @@ -202,16 +199,16 @@ def in_app?(abs_path) def compute_filename(abs_path, in_app) return nil if abs_path.nil? - under_project_root = project_root && abs_path.start_with?(project_root) + under_project_root = @project_root && abs_path.start_with?(@project_root) prefix = if under_project_root && in_app - project_root + @project_root else longest_load_path = $LOAD_PATH.select { |path| abs_path.start_with?(path.to_s) }.max_by(&:size) if under_project_root - longest_load_path || project_root + longest_load_path || @project_root else longest_load_path end diff --git a/sentry-ruby/lib/sentry/transaction.rb b/sentry-ruby/lib/sentry/transaction.rb index 1b529a0ad..fe7fb0e4d 100644 --- a/sentry-ruby/lib/sentry/transaction.rb +++ b/sentry-ruby/lib/sentry/transaction.rb @@ -292,12 +292,21 @@ def set_context(key, value) @contexts[key] = value end - # The stackprof profiler instance + # The stackprof profiler instance. # @return [Profiler, nil] def profiler return nil unless defined?(Profiler) - @profiler ||= Profiler.new + @profiler ||= Profiler.new(configuration) + end + + # Start the profiler if exists. + # @return [void] + def start_profiler! + return unless profiler + + profiler.set_initial_sample_decision(sampled) + profiler.start end protected diff --git a/sentry-ruby/spec/sentry/profiler_spec.rb b/sentry-ruby/spec/sentry/profiler_spec.rb index b0bbb033b..5607a5f82 100644 --- a/sentry-ruby/spec/sentry/profiler_spec.rb +++ b/sentry-ruby/spec/sentry/profiler_spec.rb @@ -12,6 +12,8 @@ before { StackProf.stop } + let(:subject) { described_class.new(Sentry.configuration) } + describe '#start' do context 'without sampling decision' do it 'does not start StackProf' do From cc8a4afe820ef21f9893e85927c045b9de00a4c9 Mon Sep 17 00:00:00 2001 From: Neel Shah Date: Wed, 12 Apr 2023 14:00:55 +0200 Subject: [PATCH 10/18] Implement NoopProfiler and switch on implementation if StackProf defined --- sentry-ruby/lib/sentry/profiler.rb | 34 +++++++++++++++------ sentry-ruby/lib/sentry/transaction.rb | 20 +++++------- sentry-ruby/lib/sentry/transaction_event.rb | 4 +-- sentry-ruby/spec/sentry/profiler_spec.rb | 6 ++-- 4 files changed, 35 insertions(+), 29 deletions(-) diff --git a/sentry-ruby/lib/sentry/profiler.rb b/sentry-ruby/lib/sentry/profiler.rb index 31534d29e..03a72aeb4 100644 --- a/sentry-ruby/lib/sentry/profiler.rb +++ b/sentry-ruby/lib/sentry/profiler.rb @@ -1,12 +1,24 @@ # frozen_string_literal: true -return unless defined?(StackProf) - require 'securerandom' module Sentry - class Profiler + class NoopProfiler + def initialize(_configuration); end + def start; end + def stop; end + def set_initial_sample_decision(_transaction_sampled); end + def profile_context + {} + end + + def to_hash + {} + end + end + + class StackProfProfiler < NoopProfiler VERSION = '1' PLATFORM = 'ruby' # 101 Hz in microseconds @@ -80,14 +92,14 @@ def set_initial_sample_decision(transaction_sampled) end def to_hash - return nil unless @sampled - return nil unless @started + return {} unless @sampled + return {} unless @started results = StackProf.results - return nil unless results - return nil if results.empty? - return nil if results[:samples] == 0 - return nil unless results[:raw] + return {} unless results + return {} if results.empty? + return {} if results[:samples] == 0 + return {} unless results[:raw] frame_map = {} @@ -166,7 +178,7 @@ def to_hash if samples.size <= 2 log('Not enough samples, discarding profiler') - return nil + return {} end profile = { @@ -226,4 +238,6 @@ def split_module(name) [function, mod] end end + + Profiler = defined?(StackProf) ? StackProfProfiler : NoopProfiler end diff --git a/sentry-ruby/lib/sentry/transaction.rb b/sentry-ruby/lib/sentry/transaction.rb index fe7fb0e4d..a51edae86 100644 --- a/sentry-ruby/lib/sentry/transaction.rb +++ b/sentry-ruby/lib/sentry/transaction.rb @@ -59,6 +59,10 @@ class Transaction < Span # @return [Hash] attr_reader :contexts + # The Profiler instance for this transaction. + # @return [Profiler] + attr_reader :profiler + def initialize( hub:, name: nil, @@ -84,7 +88,7 @@ def initialize( @effective_sample_rate = nil @contexts = {} @measurements = {} - @profiler = nil + @profiler = Profiler.new(@configuration) init_span_recorder end @@ -256,7 +260,7 @@ def finish(hub: nil, end_timestamp: nil) @name = UNLABELD_NAME end - @profiler&.stop + @profiler.stop if @sampled event = hub.current_client.event_from_transaction(self) @@ -292,19 +296,9 @@ def set_context(key, value) @contexts[key] = value end - # The stackprof profiler instance. - # @return [Profiler, nil] - def profiler - return nil unless defined?(Profiler) - - @profiler ||= Profiler.new(configuration) - end - - # Start the profiler if exists. + # Start the profiler. # @return [void] def start_profiler! - return unless profiler - profiler.set_initial_sample_decision(sampled) profiler.start end diff --git a/sentry-ruby/lib/sentry/transaction_event.rb b/sentry-ruby/lib/sentry/transaction_event.rb index 1ac0950b4..5ac668f92 100644 --- a/sentry-ruby/lib/sentry/transaction_event.rb +++ b/sentry-ruby/lib/sentry/transaction_event.rb @@ -58,10 +58,8 @@ def to_hash private def populate_profile(transaction) - return nil unless transaction.profiler - profile_hash = transaction.profiler.to_hash - return nil unless profile_hash + return nil if profile_hash.empty? profile_hash.merge!( environment: environment, diff --git a/sentry-ruby/spec/sentry/profiler_spec.rb b/sentry-ruby/spec/sentry/profiler_spec.rb index 5607a5f82..06f6dceec 100644 --- a/sentry-ruby/spec/sentry/profiler_spec.rb +++ b/sentry-ruby/spec/sentry/profiler_spec.rb @@ -137,12 +137,12 @@ describe '#to_hash' do it 'returns nil unless sampled' do subject.set_initial_sample_decision(false) - expect(subject.to_hash).to eq(nil) + expect(subject.to_hash).to eq({}) end it 'returns nil unless started' do subject.set_initial_sample_decision(true) - expect(subject.to_hash).to eq(nil) + expect(subject.to_hash).to eq({}) end it 'returns nil if empty results' do @@ -151,7 +151,7 @@ subject.stop expect(StackProf).to receive(:results).and_call_original - expect(subject.to_hash).to eq(nil) + expect(subject.to_hash).to eq({}) end context 'with profiled code' do From e99575b644036f1b55bd1c5e56115be2272c726d Mon Sep 17 00:00:00 2001 From: Neel Shah Date: Wed, 12 Apr 2023 14:16:36 +0200 Subject: [PATCH 11/18] Try to debug this shit --- sentry-ruby/lib/sentry/profiler.rb | 2 ++ sentry-ruby/lib/sentry/transaction_event.rb | 5 +++++ sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb | 6 ++++++ 3 files changed, 13 insertions(+) diff --git a/sentry-ruby/lib/sentry/profiler.rb b/sentry-ruby/lib/sentry/profiler.rb index 03a72aeb4..d922f0d33 100644 --- a/sentry-ruby/lib/sentry/profiler.rb +++ b/sentry-ruby/lib/sentry/profiler.rb @@ -26,6 +26,7 @@ class StackProfProfiler < NoopProfiler MICRO_TO_NANO_SECONDS = 1e3 attr_reader :sampled, :started, :event_id + attr_reader :results def initialize(configuration) @event_id = SecureRandom.uuid.delete('-') @@ -96,6 +97,7 @@ def to_hash return {} unless @started results = StackProf.results + @results = results return {} unless results return {} if results.empty? return {} if results[:samples] == 0 diff --git a/sentry-ruby/lib/sentry/transaction_event.rb b/sentry-ruby/lib/sentry/transaction_event.rb index 5ac668f92..5e5c2e1c7 100644 --- a/sentry-ruby/lib/sentry/transaction_event.rb +++ b/sentry-ruby/lib/sentry/transaction_event.rb @@ -20,6 +20,9 @@ class TransactionEvent < Event # @return [Hash, nil] attr_accessor :profile + # TODO-neel remove + attr_reader :profiler + def initialize(transaction:, **options) super(**options) @@ -36,6 +39,8 @@ def initialize(transaction:, **options) finished_spans = transaction.span_recorder.spans.select { |span| span.timestamp && span != transaction } self.spans = finished_spans.map(&:to_hash) + # TODO-neel remove + @profiler = transaction.profiler populate_profile(transaction) end diff --git a/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb b/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb index e2ab2d208..caf85504e 100644 --- a/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb +++ b/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb @@ -658,6 +658,8 @@ def will_be_sampled_by_sdk end end + before { StackProf.stop } + it "collects a profile" do app = ->(_) do [200, {}, [TestApp.foo]] @@ -667,6 +669,10 @@ def will_be_sampled_by_sdk stack.call(env) event = last_sentry_event + # TODO-neel debugging + expect(defined?(StackProf)).to eq("constant") + puts("NEEL: " + event.profiler.inspect) + profile = event.profile expect(profile).not_to be_nil From 7c7139cebec8cf53d21b9983a1b9baabf6c54ed7 Mon Sep 17 00:00:00 2001 From: Neel Shah Date: Wed, 12 Apr 2023 15:04:29 +0200 Subject: [PATCH 12/18] Revert "Try to debug this shit" This reverts commit e99575b644036f1b55bd1c5e56115be2272c726d. --- sentry-ruby/lib/sentry/profiler.rb | 2 -- sentry-ruby/lib/sentry/transaction_event.rb | 5 ----- sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb | 6 ------ 3 files changed, 13 deletions(-) diff --git a/sentry-ruby/lib/sentry/profiler.rb b/sentry-ruby/lib/sentry/profiler.rb index d922f0d33..03a72aeb4 100644 --- a/sentry-ruby/lib/sentry/profiler.rb +++ b/sentry-ruby/lib/sentry/profiler.rb @@ -26,7 +26,6 @@ class StackProfProfiler < NoopProfiler MICRO_TO_NANO_SECONDS = 1e3 attr_reader :sampled, :started, :event_id - attr_reader :results def initialize(configuration) @event_id = SecureRandom.uuid.delete('-') @@ -97,7 +96,6 @@ def to_hash return {} unless @started results = StackProf.results - @results = results return {} unless results return {} if results.empty? return {} if results[:samples] == 0 diff --git a/sentry-ruby/lib/sentry/transaction_event.rb b/sentry-ruby/lib/sentry/transaction_event.rb index 5e5c2e1c7..5ac668f92 100644 --- a/sentry-ruby/lib/sentry/transaction_event.rb +++ b/sentry-ruby/lib/sentry/transaction_event.rb @@ -20,9 +20,6 @@ class TransactionEvent < Event # @return [Hash, nil] attr_accessor :profile - # TODO-neel remove - attr_reader :profiler - def initialize(transaction:, **options) super(**options) @@ -39,8 +36,6 @@ def initialize(transaction:, **options) finished_spans = transaction.span_recorder.spans.select { |span| span.timestamp && span != transaction } self.spans = finished_spans.map(&:to_hash) - # TODO-neel remove - @profiler = transaction.profiler populate_profile(transaction) end diff --git a/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb b/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb index caf85504e..e2ab2d208 100644 --- a/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb +++ b/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb @@ -658,8 +658,6 @@ def will_be_sampled_by_sdk end end - before { StackProf.stop } - it "collects a profile" do app = ->(_) do [200, {}, [TestApp.foo]] @@ -669,10 +667,6 @@ def will_be_sampled_by_sdk stack.call(env) event = last_sentry_event - # TODO-neel debugging - expect(defined?(StackProf)).to eq("constant") - puts("NEEL: " + event.profiler.inspect) - profile = event.profile expect(profile).not_to be_nil From cd5dc0a59560b049696039222ff3d9080a9b467e Mon Sep 17 00:00:00 2001 From: Neel Shah Date: Wed, 12 Apr 2023 15:06:23 +0200 Subject: [PATCH 13/18] Stub stackprof for rack as well, since results is unreliable --- .../sentry/rack/capture_exceptions_spec.rb | 22 +++++++++++-------- 1 file changed, 13 insertions(+), 9 deletions(-) diff --git a/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb b/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb index e2ab2d208..964c24ed1 100644 --- a/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb +++ b/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb @@ -1,13 +1,6 @@ -# return unless defined?(Rack) - require 'spec_helper' -module TestApp - def self.foo - sleep 0.1 - "ok" - end -end +return unless defined?(Rack) RSpec.describe Sentry::Rack::CaptureExceptions, rack: true do let(:exception) { ZeroDivisionError.new("divided by 0") } @@ -658,9 +651,20 @@ def will_be_sampled_by_sdk end end + let(:stackprof_results) do + data = StackProf::Report.from_file('spec/support/stackprof_results.json').data + # relative dir differs on each machine + data[:frames].each { |_id, fra| fra[:file].gsub!(//, Dir.pwd) } + data + end + + before do + allow(StackProf).to receive(:results).and_return(stackprof_results) + end + it "collects a profile" do app = ->(_) do - [200, {}, [TestApp.foo]] + [200, {}, "ok"] end stack = described_class.new(app) From 207fc047863a78b2c90a3bf4da76024043a7c802 Mon Sep 17 00:00:00 2001 From: Neel Shah Date: Wed, 12 Apr 2023 15:28:15 +0200 Subject: [PATCH 14/18] reeeeeee --- sentry-ruby/lib/sentry/transaction_event.rb | 2 +- sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb | 1 + 2 files changed, 2 insertions(+), 1 deletion(-) diff --git a/sentry-ruby/lib/sentry/transaction_event.rb b/sentry-ruby/lib/sentry/transaction_event.rb index 5ac668f92..12dd9897e 100644 --- a/sentry-ruby/lib/sentry/transaction_event.rb +++ b/sentry-ruby/lib/sentry/transaction_event.rb @@ -59,7 +59,7 @@ def to_hash def populate_profile(transaction) profile_hash = transaction.profiler.to_hash - return nil if profile_hash.empty? + return if profile_hash.empty? profile_hash.merge!( environment: environment, diff --git a/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb b/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb index 964c24ed1..34d735a21 100644 --- a/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb +++ b/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb @@ -659,6 +659,7 @@ def will_be_sampled_by_sdk end before do + StackProf.stop allow(StackProf).to receive(:results).and_return(stackprof_results) end From d345a3af5c9130d0f9b01e594677490c2f73bbc6 Mon Sep 17 00:00:00 2001 From: Neel Shah Date: Wed, 12 Apr 2023 15:38:38 +0200 Subject: [PATCH 15/18] Change stackprof conditionals --- sentry-ruby/spec/sentry/profiler_spec.rb | 2 +- .../sentry/rack/capture_exceptions_spec.rb | 124 +++++++++--------- 2 files changed, 64 insertions(+), 62 deletions(-) diff --git a/sentry-ruby/spec/sentry/profiler_spec.rb b/sentry-ruby/spec/sentry/profiler_spec.rb index 06f6dceec..a1d3f9269 100644 --- a/sentry-ruby/spec/sentry/profiler_spec.rb +++ b/sentry-ruby/spec/sentry/profiler_spec.rb @@ -1,6 +1,6 @@ require "spec_helper" -return unless defined?(Sentry::Profiler) +return unless defined?(StackProf) RSpec.describe Sentry::Profiler do before do diff --git a/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb b/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb index 34d735a21..d964a866f 100644 --- a/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb +++ b/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb @@ -641,73 +641,75 @@ def will_be_sampled_by_sdk end end - describe "profiling" do - context "when profiling is enabled" do - before do - perform_basic_setup do |config| - config.traces_sample_rate = 1.0 - config.profiles_sample_rate = 1.0 - config.release = "test-release" + if defined?(StackProf) + describe "profiling" do + context "when profiling is enabled" do + before do + perform_basic_setup do |config| + config.traces_sample_rate = 1.0 + config.profiles_sample_rate = 1.0 + config.release = "test-release" + end end - end - - let(:stackprof_results) do - data = StackProf::Report.from_file('spec/support/stackprof_results.json').data - # relative dir differs on each machine - data[:frames].each { |_id, fra| fra[:file].gsub!(//, Dir.pwd) } - data - end - before do - StackProf.stop - allow(StackProf).to receive(:results).and_return(stackprof_results) - end + let(:stackprof_results) do + data = StackProf::Report.from_file('spec/support/stackprof_results.json').data + # relative dir differs on each machine + data[:frames].each { |_id, fra| fra[:file].gsub!(//, Dir.pwd) } + data + end - it "collects a profile" do - app = ->(_) do - [200, {}, "ok"] + before do + StackProf.stop + allow(StackProf).to receive(:results).and_return(stackprof_results) end - stack = described_class.new(app) - stack.call(env) - event = last_sentry_event + it "collects a profile" do + app = ->(_) do + [200, {}, "ok"] + end + + stack = described_class.new(app) + stack.call(env) + event = last_sentry_event + + profile = event.profile + expect(profile).not_to be_nil - profile = event.profile - expect(profile).not_to be_nil - - expect(profile[:event_id]).not_to be_nil - expect(event.contexts[:profile]).to eq({ profile_id: profile[:event_id] }) - - expect(profile[:platform]).to eq("ruby") - expect(profile[:version]).to eq("1") - expect(profile[:environment]).to eq("development") - expect(profile[:release]).to eq("test-release") - expect { Time.parse(profile[:timestamp]) }.not_to raise_error - - expect(profile[:device]).to include(:architecture) - expect(profile[:os]).to include(:name, :version) - expect(profile[:runtime]).to include(:name, :version) - - expect(profile[:transaction]).to include(:id, :name, :trace_id, :active_thead_id) - expect(profile[:transaction][:id]).to eq(event.event_id) - expect(profile[:transaction][:name]).to eq(event.transaction) - expect(profile[:transaction][:trace_id]).to eq(event.contexts[:trace][:trace_id]) - expect(profile[:transaction][:active_thead_id]).to eq("0") - - # detailed checking of content is done in profiler_spec, - # just check basic structure here - frames = profile[:profile][:frames] - expect(frames).to be_a(Array) - expect(frames.first).to include(:function, :filename, :abs_path, :in_app) - - stacks = profile[:profile][:stacks] - expect(stacks).to be_a(Array) - expect(stacks.first).to be_a(Array) - expect(stacks.first.first).to be_a(Integer) - - samples = profile[:profile][:samples] - expect(samples).to be_a(Array) - expect(samples.first).to include(:stack_id, :thread_id, :elapsed_since_start_ns) + expect(profile[:event_id]).not_to be_nil + expect(event.contexts[:profile]).to eq({ profile_id: profile[:event_id] }) + + expect(profile[:platform]).to eq("ruby") + expect(profile[:version]).to eq("1") + expect(profile[:environment]).to eq("development") + expect(profile[:release]).to eq("test-release") + expect { Time.parse(profile[:timestamp]) }.not_to raise_error + + expect(profile[:device]).to include(:architecture) + expect(profile[:os]).to include(:name, :version) + expect(profile[:runtime]).to include(:name, :version) + + expect(profile[:transaction]).to include(:id, :name, :trace_id, :active_thead_id) + expect(profile[:transaction][:id]).to eq(event.event_id) + expect(profile[:transaction][:name]).to eq(event.transaction) + expect(profile[:transaction][:trace_id]).to eq(event.contexts[:trace][:trace_id]) + expect(profile[:transaction][:active_thead_id]).to eq("0") + + # detailed checking of content is done in profiler_spec, + # just check basic structure here + frames = profile[:profile][:frames] + expect(frames).to be_a(Array) + expect(frames.first).to include(:function, :filename, :abs_path, :in_app) + + stacks = profile[:profile][:stacks] + expect(stacks).to be_a(Array) + expect(stacks.first).to be_a(Array) + expect(stacks.first.first).to be_a(Integer) + + samples = profile[:profile][:samples] + expect(samples).to be_a(Array) + expect(samples.first).to include(:stack_id, :thread_id, :elapsed_since_start_ns) + end end end end From 227e5d3310914f316ad04d1de59801e331408d45 Mon Sep 17 00:00:00 2001 From: Neel Shah Date: Thu, 13 Apr 2023 16:18:30 +0200 Subject: [PATCH 16/18] CHANGELOG --- CHANGELOG.md | 38 +++++++++++++++++++++++++++++++++++++- 1 file changed, 37 insertions(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 0480a507b..259862a46 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,7 @@ - `config.enable_tracing = false` will turn off tracing even if `traces_sample_rate/traces_sampler` is set - `config.enable_tracing = nil` (default) will keep the current behaviour - Allow ignoring `excluded_exceptions` when manually capturing exceptions [#2007](https://github.com/getsentry/sentry-ruby/pull/2007) + Users can now ignore the SDK's `excluded_exceptions` by passing `ignore_exclusions` hint when using `Sentry.capture_exception`. ```rb @@ -14,9 +15,44 @@ Sentry.capture_exception(ignored_exception) # won't be sent to Sentry Sentry.capture_exception(ignored_exception, hint: { ignore_exclusions: true }) # will be sent to Sentry ``` + - Add `spec` to `Backtrace::APP_DIRS_PATTERN` [#2029](https://github.com/getsentry/sentry-ruby/pull/2029) - Forward all `baggage` header items that are prefixed with `sentry-` [#2025](https://github.com/getsentry/sentry-ruby/pull/2025) -- Profiling TODO-neel-profiler changelog entry +- Add `stackprof` based profiler [#2024](https://github.com/getsentry/sentry-ruby/pull/2024) + + The SDK now supports sending profiles taken by the [`stackprof` gem](https://github.com/tmm1/stackprof) and viewing them in the [Profiling](https://docs.sentry.io/product/profiling/) section. + + To use it, first add `stackprof` to your `Gemfile` and make sure it is loaded before `sentry-ruby`. + + ```ruby + # Gemfile + + gem 'stackprof' + gem 'sentry-ruby' + ``` + + Then, make sure both `traces_sample_rate` and `profiles_sample_rate` are set and non-zero in your sentry initializer. + + ```ruby + # config/initializers/sentry.rb + + Sentry.init do |config| + config.dsn = "" + config.traces_sample_rate = 1.0 + config.profiles_sample_rate = 1.0 + end + ``` + + Some implementation caveats: + - Profiles are sampled **relative** to traces, so if both rates are 0.5, we will capture 0.25 of all requests. + - Profiles are only captured for code running within a transaction. + - Profiles for multi-threaded servers like `puma` might not capture frames correctly when async I/O is happening. This is a `stackprof` limitation. + +
+ + > **Warning** + > Profiling is currently in beta. Beta features are still in-progress and may have bugs. We recognize the irony. + > If you have any questions or feedback, please email us at profiling@sentry.io, reach out via Discord (#profiling), or open an issue. ### Bug Fixes From d6ba93f8a1cb289633cc84bbc299bee2596aa17a Mon Sep 17 00:00:00 2001 From: Neel Shah Date: Mon, 17 Apr 2023 15:09:46 +0200 Subject: [PATCH 17/18] Get rid of NoopProfiler and just augment profiling_enabled? check --- sentry-ruby/lib/sentry/profiler.rb | 21 ++------------------- 1 file changed, 2 insertions(+), 19 deletions(-) diff --git a/sentry-ruby/lib/sentry/profiler.rb b/sentry-ruby/lib/sentry/profiler.rb index 03a72aeb4..09cb1fdeb 100644 --- a/sentry-ruby/lib/sentry/profiler.rb +++ b/sentry-ruby/lib/sentry/profiler.rb @@ -3,22 +3,7 @@ require 'securerandom' module Sentry - class NoopProfiler - def initialize(_configuration); end - def start; end - def stop; end - def set_initial_sample_decision(_transaction_sampled); end - - def profile_context - {} - end - - def to_hash - {} - end - end - - class StackProfProfiler < NoopProfiler + class Profiler VERSION = '1' PLATFORM = 'ruby' # 101 Hz in microseconds @@ -32,7 +17,7 @@ def initialize(configuration) @started = false @sampled = nil - @profiling_enabled = configuration.profiling_enabled? + @profiling_enabled = defined?(StackProf) && configuration.profiling_enabled? @profiles_sample_rate = configuration.profiles_sample_rate @project_root = configuration.project_root @app_dirs_pattern = configuration.app_dirs_pattern || Backtrace::APP_DIRS_PATTERN @@ -238,6 +223,4 @@ def split_module(name) [function, mod] end end - - Profiler = defined?(StackProf) ? StackProfProfiler : NoopProfiler end From ec0a24f210116800b64e7eadc6e4cb1f9f7717e8 Mon Sep 17 00:00:00 2001 From: Neel Shah Date: Mon, 17 Apr 2023 15:22:42 +0200 Subject: [PATCH 18/18] Remove profile_context, no longer necessary --- sentry-ruby/lib/sentry/profiler.rb | 4 ---- sentry-ruby/lib/sentry/transaction_event.rb | 1 - sentry-ruby/spec/sentry/profiler_spec.rb | 6 ------ sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb | 2 -- 4 files changed, 13 deletions(-) diff --git a/sentry-ruby/lib/sentry/profiler.rb b/sentry-ruby/lib/sentry/profiler.rb index 09cb1fdeb..e5bed005e 100644 --- a/sentry-ruby/lib/sentry/profiler.rb +++ b/sentry-ruby/lib/sentry/profiler.rb @@ -43,10 +43,6 @@ def stop log('Stopped') end - def profile_context - { profile_id: @event_id } - end - # Sets initial sampling decision of the profile. # @return [void] def set_initial_sample_decision(transaction_sampled) diff --git a/sentry-ruby/lib/sentry/transaction_event.rb b/sentry-ruby/lib/sentry/transaction_event.rb index 12dd9897e..9b3f6909f 100644 --- a/sentry-ruby/lib/sentry/transaction_event.rb +++ b/sentry-ruby/lib/sentry/transaction_event.rb @@ -78,7 +78,6 @@ def populate_profile(transaction) ) self.profile = profile_hash - self.contexts.merge!(profile: transaction.profiler.profile_context) end end end diff --git a/sentry-ruby/spec/sentry/profiler_spec.rb b/sentry-ruby/spec/sentry/profiler_spec.rb index a1d3f9269..ec54efebb 100644 --- a/sentry-ruby/spec/sentry/profiler_spec.rb +++ b/sentry-ruby/spec/sentry/profiler_spec.rb @@ -77,12 +77,6 @@ end end - describe '#profile_context' do - it 'returns profile context hash' do - expect(subject.profile_context).to eq({ profile_id: subject.event_id }) - end - end - describe '#set_initial_sample_decision' do context 'with profiling disabled' do it 'does not sample when profiles_sample_rate is nil' do diff --git a/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb b/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb index d964a866f..7429b2d0d 100644 --- a/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb +++ b/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb @@ -677,8 +677,6 @@ def will_be_sampled_by_sdk expect(profile).not_to be_nil expect(profile[:event_id]).not_to be_nil - expect(event.contexts[:profile]).to eq({ profile_id: profile[:event_id] }) - expect(profile[:platform]).to eq("ruby") expect(profile[:version]).to eq("1") expect(profile[:environment]).to eq("development")