From bd687cc55f5edd578004d10fa95f9242df26997f Mon Sep 17 00:00:00 2001 From: Peter Solnica Date: Wed, 14 Aug 2024 18:13:53 +0000 Subject: [PATCH] Add support for Vernier profiler - Introduce `Sentry::Vernier::Profiler` - Introduce `Sentry.config.profiler` that can be set to a class that should be used for profiling. By default it's set to `Sentry::Profiler` --- sentry-ruby/Gemfile | 4 +- sentry-ruby/lib/sentry/configuration.rb | 6 + sentry-ruby/lib/sentry/profiler.rb | 40 +-- sentry-ruby/lib/sentry/profiler/helpers.rb | 46 +++ sentry-ruby/lib/sentry/transaction.rb | 2 +- sentry-ruby/lib/sentry/transaction_event.rb | 3 +- sentry-ruby/lib/sentry/vernier/output.rb | 97 ++++++ sentry-ruby/lib/sentry/vernier/profiler.rb | 126 +++++++ .../sentry/rack/capture_exceptions_spec.rb | 138 ++++---- .../spec/sentry/vernier/profiler_spec.rb | 308 ++++++++++++++++++ sentry-ruby/spec/spec_helper.rb | 7 + sentry-ruby/spec/support/profiler.rb | 14 + 12 files changed, 694 insertions(+), 97 deletions(-) create mode 100644 sentry-ruby/lib/sentry/profiler/helpers.rb create mode 100644 sentry-ruby/lib/sentry/vernier/output.rb create mode 100644 sentry-ruby/lib/sentry/vernier/profiler.rb create mode 100644 sentry-ruby/spec/sentry/vernier/profiler_spec.rb create mode 100644 sentry-ruby/spec/support/profiler.rb diff --git a/sentry-ruby/Gemfile b/sentry-ruby/Gemfile index c6e1db011..67f58e64b 100644 --- a/sentry-ruby/Gemfile +++ b/sentry-ruby/Gemfile @@ -5,7 +5,8 @@ gem "sentry-ruby", path: "./" rack_version = ENV["RACK_VERSION"] rack_version = "3.0.0" if rack_version.nil? -gem "rack", "~> #{Gem::Version.new(rack_version)}" unless rack_version == "0" +# gem "rack", "~> #{Gem::Version.new(rack_version)}" unless rack_version == "0" +gem "rack", "~> 3.1" redis_rb_version = ENV.fetch("REDIS_RB_VERSION", "5.0") gem "redis", "~> #{redis_rb_version}" @@ -14,6 +15,7 @@ gem "puma" gem "timecop" gem "stackprof" unless RUBY_PLATFORM == "java" +gem "vernier", platforms: :ruby if RUBY_VERSION >= "3.2.1" gem "graphql", ">= 2.2.6" if RUBY_VERSION.to_f >= 2.7 diff --git a/sentry-ruby/lib/sentry/configuration.rb b/sentry-ruby/lib/sentry/configuration.rb index 4fb927cb4..5f27c2ac2 100644 --- a/sentry-ruby/lib/sentry/configuration.rb +++ b/sentry-ruby/lib/sentry/configuration.rb @@ -284,6 +284,10 @@ def capture_exception_frame_locals=(value) # @return [Symbol] attr_reader :instrumenter + # The profiler class + # @return [Class] + attr_accessor :profiler + # 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. @@ -393,6 +397,8 @@ def initialize self.traces_sampler = nil self.enable_tracing = nil + self.profiler = Sentry::Profiler + @transport = Transport::Configuration.new @cron = Cron::Configuration.new @metrics = Metrics::Configuration.new diff --git a/sentry-ruby/lib/sentry/profiler.rb b/sentry-ruby/lib/sentry/profiler.rb index cec7c70ce..638280483 100644 --- a/sentry-ruby/lib/sentry/profiler.rb +++ b/sentry-ruby/lib/sentry/profiler.rb @@ -1,9 +1,12 @@ # frozen_string_literal: true require "securerandom" +require_relative "profiler/helpers" module Sentry class Profiler + include Profiler::Helpers + VERSION = "1" PLATFORM = "ruby" # 101 Hz in microseconds @@ -189,43 +192,6 @@ 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 - def record_lost_event(reason) Sentry.get_current_client&.transport&.record_lost_event(reason, "profile") end diff --git a/sentry-ruby/lib/sentry/profiler/helpers.rb b/sentry-ruby/lib/sentry/profiler/helpers.rb new file mode 100644 index 000000000..3c446fba0 --- /dev/null +++ b/sentry-ruby/lib/sentry/profiler/helpers.rb @@ -0,0 +1,46 @@ +# frozen_string_literal: true + +require "securerandom" + +module Sentry + class Profiler + module Helpers + 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 diff --git a/sentry-ruby/lib/sentry/transaction.rb b/sentry-ruby/lib/sentry/transaction.rb index ac6256555..ed77d8d65 100644 --- a/sentry-ruby/lib/sentry/transaction.rb +++ b/sentry-ruby/lib/sentry/transaction.rb @@ -85,7 +85,7 @@ def initialize( @effective_sample_rate = nil @contexts = {} @measurements = {} - @profiler = Profiler.new(@configuration) + @profiler = @configuration.profiler.new(@configuration) init_span_recorder end diff --git a/sentry-ruby/lib/sentry/transaction_event.rb b/sentry-ruby/lib/sentry/transaction_event.rb index 4136ac6aa..9c015227c 100644 --- a/sentry-ruby/lib/sentry/transaction_event.rb +++ b/sentry-ruby/lib/sentry/transaction_event.rb @@ -74,8 +74,7 @@ def populate_profile(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" + active_thread_id: Thread.current.object_id.to_s } ) diff --git a/sentry-ruby/lib/sentry/vernier/output.rb b/sentry-ruby/lib/sentry/vernier/output.rb new file mode 100644 index 000000000..d67b69602 --- /dev/null +++ b/sentry-ruby/lib/sentry/vernier/output.rb @@ -0,0 +1,97 @@ +# frozen_string_literal: true + +require "json" +require "rbconfig" + +module Sentry + module Vernier + class Output + include Profiler::Helpers + + attr_reader :profile + + def initialize(profile, project_root:, in_app_pattern:, app_dirs_pattern:) + @profile = profile + @project_root = project_root + @in_app_pattern = in_app_pattern + @app_dirs_pattern = app_dirs_pattern + end + + def to_h + @to_h ||= { + frames: frames, + stacks: stacks, + samples: samples, + thread_metadata: thread_metadata + } + end + + private + + def thread_metadata + profile.threads.map { |thread_id, thread_info| + [thread_id, { name: thread_info[:name] }] + }.to_h + end + + def samples + profile.threads.flat_map { |thread_id, thread_info| + started_at = thread_info[:started_at] + samples, timestamps = thread_info.values_at(:samples, :timestamps) + + samples.zip(timestamps).map { |stack_id, timestamp| + elapsed_since_start_ns = timestamp - started_at + + next if elapsed_since_start_ns < 0 + + { + thread_id: thread_id.to_s, + stack_id: stack_id, + elapsed_since_start_ns: elapsed_since_start_ns.to_s + } + }.compact + } + end + + def frames + funcs = stack_table_hash[:frame_table].fetch(:func) + lines = stack_table_hash[:func_table].fetch(:first_line) + + funcs.map { |idx| + function, mod = split_module(stack_table_hash[:func_table][:name][idx]) + + abs_path = stack_table_hash[:func_table][:filename][idx] + in_app = in_app?(abs_path) + filename = compute_filename(abs_path, in_app) + + { + function: function, + module: mod, + filename: filename, + abs_path: abs_path, + lineno: (lineno = lines[idx]) > 0 ? lineno : nil, + in_app: in_app + }.compact + } + end + + def stacks + sample_stacks = profile.threads.flat_map { |_, thread_info| + samples = thread_info[:samples].map { |stack_id| profile.stack(stack_id) } + + samples.map { |stack| [stack.idx, stack.frames.map(&:idx)] } + }.to_h + + stacks = profile._stack_table.stack_count.times.map do |stack_id| + (sample_stacks[stack_id] || profile.stack(stack_id).frames.map(&:idx)) + end + + stacks + end + + def stack_table_hash + @stack_table_hash ||= profile._stack_table.to_h + end + end + end +end diff --git a/sentry-ruby/lib/sentry/vernier/profiler.rb b/sentry-ruby/lib/sentry/vernier/profiler.rb new file mode 100644 index 000000000..92d0d43d3 --- /dev/null +++ b/sentry-ruby/lib/sentry/vernier/profiler.rb @@ -0,0 +1,126 @@ +# frozen_string_literal: true + +require "securerandom" +require_relative "../profiler/helpers" +require_relative "output" + +begin + require "vernier" +rescue LoadError +end + +module Sentry + module Vernier + class Profiler + EMPTY_RESULT = {}.freeze + + attr_reader :started, :event_id, :result + + def initialize(configuration) + @event_id = SecureRandom.uuid.delete("-") + + @started = false + @sampled = nil + + @profiling_enabled = defined?(Vernier) && 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 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 + + 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 start + return unless @sampled && !@started + + ::Vernier.start_profile + @started = true + + log("Started") + + @started + rescue RuntimeError => e + # TODO: once Vernier raises something more dedicated, we should catch that instead + if e.message.include?("Profile already started") + log("Not started since running elsewhere") + else + log("Failed to start: #{e.message}") + raise e + end + end + + def stop + return unless @sampled + return unless @started + + @result = ::Vernier.stop_profile + + log("Stopped") + end + + def to_hash + return EMPTY_RESULT unless @started + + unless @sampled + record_lost_event(:sample_rate) + return EMPTY_RESULT + end + + { **profile_meta, profile: output.to_h } + end + + private + + def log(message) + Sentry.logger.debug(LOGGER_PROGNAME) { "[Profiler::Vernier] #{message}" } + end + + def record_lost_event(reason) + Sentry.get_current_client&.transport&.record_lost_event(reason, "profile") + end + + def profile_meta + { + event_id: @event_id, + version: "1", + platform: "ruby" + } + end + + def output + @output ||= Output.new( + result, + project_root: @project_root, + app_dirs_pattern: @app_dirs_pattern, + in_app_pattern: @in_app_pattern + ) + 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 dfd42ab33..1f78dad46 100644 --- a/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb +++ b/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb @@ -679,74 +679,100 @@ def will_be_sampled_by_sdk end end - 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 + shared_examples "a profiled transaction" do + it "collects a profile", retry: 3 do + stack = Sentry::Rack::CaptureExceptions.new(app) + stack.call(env) + event = last_sentry_event - 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 + profile = event.profile + expect(profile).not_to be_nil + + expect(profile[:event_id]).not_to be_nil + 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_thread_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_thread_id]).to eq(Thread.current.object_id.to_s) + + # 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 - before do - StackProf.stop - allow(StackProf).to receive(:results).and_return(stackprof_results) + describe "profiling with StackProf", when: :stack_prof_installed? do + context "when profiling is enabled" do + let(:app) do + ->(_) do + [200, {}, "ok"] end + end - it "collects a profile" do - app = ->(_) do - [200, {}, "ok"] - end - - stack = Sentry::Rack::CaptureExceptions.new(app) - stack.call(env) - event = last_sentry_event - - profile = event.profile - expect(profile).not_to be_nil + 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 - expect(profile[:event_id]).not_to be_nil - 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 + before do + perform_basic_setup do |config| + config.traces_sample_rate = 1.0 + config.profiles_sample_rate = 1.0 + config.release = "test-release" + end - expect(profile[:device]).to include(:architecture) - expect(profile[:os]).to include(:name, :version) - expect(profile[:runtime]).to include(:name, :version) + StackProf.stop - 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") + allow(StackProf).to receive(:results).and_return(stackprof_results) + end - # 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) + include_examples "a profiled transaction" + end + end - 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) + describe "profiling with vernier", when: :vernier_installed? do + context "when profiling is enabled" do + let(:app) do + ->(_) do + ProfilerTest::Bar.bar + [200, {}, "ok"] + end + end - samples = profile[:profile][:samples] - expect(samples).to be_a(Array) - expect(samples.first).to include(:stack_id, :thread_id, :elapsed_since_start_ns) + before do + perform_basic_setup do |config| + config.traces_sample_rate = 1.0 + config.profiles_sample_rate = 1.0 + config.release = "test-release" + config.profiler = Sentry::Vernier::Profiler + config.project_root = Dir.pwd end end + + include_examples "a profiled transaction" end end end diff --git a/sentry-ruby/spec/sentry/vernier/profiler_spec.rb b/sentry-ruby/spec/sentry/vernier/profiler_spec.rb new file mode 100644 index 000000000..881f1b24d --- /dev/null +++ b/sentry-ruby/spec/sentry/vernier/profiler_spec.rb @@ -0,0 +1,308 @@ +require "spec_helper" + +require "sentry/vernier/profiler" + +RSpec.describe Sentry::Vernier::Profiler, when: [:ruby_version?, :>=, "3.2.1"] do + subject(:profiler) { described_class.new(Sentry.configuration) } + + before do + # TODO: replace with some public API once available + Vernier.stop_profile if Vernier.instance_variable_get(:@collector) + + perform_basic_setup do |config| + config.traces_sample_rate = traces_sample_rate + config.profiles_sample_rate = profiles_sample_rate + end + end + + let(:profiles_sample_rate) { 1.0 } + let(:traces_sample_rate) { 1.0 } + + describe '#start' do + context "when profiles_sample_rate is 0" do + let(:profiles_sample_rate) { 0.0 } + + it "does not start Vernier" do + profiler.set_initial_sample_decision(true) + + expect(Vernier).not_to receive(:start_profile) + profiler.start + expect(profiler.started).to eq(false) + end + end + + context "when profiles_sample_rate is between 0.0 and 1.0" do + let(:profiles_sample_rate) { 0.4 } + + it "randomizes profiling" do + profiler.set_initial_sample_decision(true) + + expect([nil, true]).to include(profiler.start) + end + end + + context "when traces_sample_rate is nil" do + let(:traces_sample_rate) { nil } + + it "does not start Vernier" do + profiler.set_initial_sample_decision(true) + + expect(Vernier).not_to receive(:start_profile) + profiler.start + expect(profiler.started).to eq(false) + end + end + + context 'without sampling decision' do + it 'does not start Vernier' do + expect(Vernier).not_to receive(:start_profile) + profiler.start + expect(profiler.started).to eq(false) + end + + it 'does not start Vernier if not sampled' do + expect(Vernier).not_to receive(:start_profile) + profiler.start + expect(profiler.started).to eq(false) + end + end + + context 'with sampling decision' do + before do + profiler.set_initial_sample_decision(true) + end + + it 'starts Vernier if sampled' do + expect(Vernier).to receive(:start_profile).and_return(true) + + profiler.start + + expect(profiler.started).to eq(true) + end + + it 'does not start Vernier again if already started' do + expect(Vernier).to receive(:start_profile).and_return(true).once + + profiler.start + profiler.start + + expect(profiler.started).to be(true) + end + end + + context "when Vernier crashes" do + it "logs the error and re-raises" do + profiler.set_initial_sample_decision(true) + + expect(Vernier).to receive(:start_profile).and_raise("boom") + + expect { profiler.start }.to raise_error("boom") + end + + it "doesn't start if Vernier raises that it already started" do + profiler.set_initial_sample_decision(true) + + expect(Vernier).to receive(:start_profile).and_raise(RuntimeError.new("Profile already started")) + + profiler.start + + expect(profiler.started).to eq(false) + end + end + end + + describe '#stop' do + it 'does not stop Vernier if not sampled' do + profiler.set_initial_sample_decision(false) + expect(Vernier).not_to receive(:stop_profile) + profiler.stop + end + + it 'does not stop Vernier if sampled but not started' do + profiler.set_initial_sample_decision(true) + expect(Vernier).not_to receive(:stop_profile) + profiler.stop + end + + it 'stops Vernier if sampled and started' do + profiler.set_initial_sample_decision(true) + profiler.start + expect(Vernier).to receive(:stop_profile) + profiler.stop + end + end + + describe "#to_hash" do + let (:transport) { Sentry.get_current_client.transport } + + + it "records lost event if not sampled" do + expect(transport).to receive(:record_lost_event).with(:sample_rate, "profile") + + profiler.set_initial_sample_decision(true) + profiler.start + profiler.set_initial_sample_decision(false) + + expect(profiler.to_hash).to eq({}) + end + end + + context 'with sampling decision' do + before do + profiler.set_initial_sample_decision(true) + end + + describe '#to_hash' do + it "returns empty hash if not started" do + expect(profiler.to_hash).to eq({}) + end + + context 'with single-thread profiled code' do + before do + profiler.start + ProfilerTest::Bar.bar + profiler.stop + end + + it 'has correct frames' do + frames = profiler.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('ProfilerTest::Bar') + expect(foo_frame[:in_app]).to eq(true) + expect(foo_frame[:lineno]).to eq(4) + expect(foo_frame[:filename]).to eq('spec/support/profiler.rb') + expect(foo_frame[:abs_path]).to include('sentry-ruby/sentry-ruby/spec/support/profiler.rb') + end + + it 'has correct stacks' do + profile = profiler.to_hash[:profile] + frames = profile[:frames] + stacks = profile[:stacks] + + stack_tops = stacks.map { |s| s.take(3) }.map { |s| s.map { |i| frames[i][:function] } } + + expect(stack_tops.any? { |tops| tops.include?("Foo.foo") }).to be(true) + expect(stack_tops.any? { |tops| tops.include?("Bar.bar") }).to be(true) + expect(stack_tops.any? { |tops| tops.include?("Integer#times") }).to be(true) + + stacks.each do |stack| + stack.each do |frame_idx| + expect(frames[frame_idx][:function]).to be_a(String) + end + end + end + + it 'has correct samples' do + profile = profiler.to_hash[:profile] + samples = profile[:samples] + last_elapsed = 0 + + samples.group_by { |sample| sample[:thread_id] }.each do |thread_id, thread_samples| + expect(thread_id.to_i).to be > 0 + + last_elapsed = 0 + + thread_samples.each do |sample| + expect(sample[:stack_id]).to be > 0 + + elapsed = sample[:elapsed_since_start_ns].to_i + + expect(elapsed).to be > 0.0 + expect(elapsed).to be > last_elapsed + + last_elapsed = elapsed + end + end + end + end + + context 'with multi-thread profiled code' do + before do + profiler.start + + 2.times.map do |i| + Thread.new do + Thread.current.name = "thread-bar-#{i}" + + ProfilerTest::Bar.bar + end + end.map(&:join) + + profiler.stop + end + + it "has correct thread metadata" do + thread_metadata = profiler.to_hash[:profile][:thread_metadata] + + main_thread = thread_metadata.values.find { |metadata| metadata[:name].include?("rspec") } + thread1 = thread_metadata.values.find { |metadata| metadata[:name] == "thread-bar-0" } + thread2 = thread_metadata.values.find { |metadata| metadata[:name] == "thread-bar-1" } + + thread_metadata.each do |thread_id, metadata| + expect(thread_id.to_i).to be > 0 + end + + expect(main_thread[:name]).to include("rspec") + expect(thread1[:name]).to eq("thread-bar-0") + expect(thread2[:name]).to eq("thread-bar-1") + end + + it 'has correct frames', when: [:ruby_version?, :>=, "3.3"] do + frames = profiler.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('ProfilerTest::Bar') + expect(foo_frame[:in_app]).to eq(true) + expect(foo_frame[:lineno]).to eq(4) + expect(foo_frame[:filename]).to eq('spec/support/profiler.rb') + expect(foo_frame[:abs_path]).to include('sentry-ruby/sentry-ruby/spec/support/profiler.rb') + end + + it 'has correct stacks', when: [:ruby_version?, :>=, "3.3"] do + profile = profiler.to_hash[:profile] + frames = profile[:frames] + stacks = profile[:stacks] + + stack_tops = stacks.map { |s| s.take(3) }.map { |s| s.map { |i| frames[i][:function] } } + + expect(stack_tops.any? { |tops| tops.include?("Foo.foo") }).to be(true) + expect(stack_tops.any? { |tops| tops.include?("Bar.bar") }).to be(true) + expect(stack_tops.any? { |tops| tops.include?("Integer#times") }).to be(true) + + stacks.each do |stack| + stack.each do |frame_idx| + expect(frames[frame_idx][:function]).to be_a(String) + end + end + end + + it 'has correct samples' do + profile = profiler.to_hash[:profile] + samples = profile[:samples] + + samples.group_by { |sample| sample[:thread_id] }.each do |thread_id, thread_samples| + expect(thread_id.to_i).to be > 0 + + last_elapsed = 0 + + thread_samples.each do |sample| + expect(sample[:stack_id]).to be > 0 + + elapsed = sample[:elapsed_since_start_ns].to_i + + expect(elapsed).to be > 0.0 + expect(elapsed).to be > last_elapsed + + last_elapsed = elapsed + end + end + end + end + end + end +end diff --git a/sentry-ruby/spec/spec_helper.rb b/sentry-ruby/spec/spec_helper.rb index f347f0664..511ea6a56 100644 --- a/sentry-ruby/spec/spec_helper.rb +++ b/sentry-ruby/spec/spec_helper.rb @@ -23,6 +23,8 @@ require "sentry-ruby" require "sentry/test_helper" +Dir[Pathname(__dir__).join("support/**/*.rb")].sort.each { |f| require f } + RSpec.configure do |config| # Enable flags like --only-failures and --next-failure config.example_status_persistence_file_path = ".rspec_status" @@ -64,6 +66,11 @@ def self.stack_prof_installed? defined?(StackProf) end + def self.vernier_installed? + require "sentry/vernier/profiler" + defined?(::Vernier) + end + def self.rack_available? defined?(Rack) end diff --git a/sentry-ruby/spec/support/profiler.rb b/sentry-ruby/spec/support/profiler.rb new file mode 100644 index 000000000..7f048b8a5 --- /dev/null +++ b/sentry-ruby/spec/support/profiler.rb @@ -0,0 +1,14 @@ +module ProfilerTest + 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 +end