From 7b00b250968164cb4bb6ee7ac4a777dc2e868252 Mon Sep 17 00:00:00 2001 From: Stan Lo Date: Fri, 31 May 2024 14:40:42 +0100 Subject: [PATCH] Add query source support to `sentry-rails` (#2313) * Support query source in ActiveRecord spans This change mimics Rails' ActiveRecord::LogSubscriber to extract the source of the query and add it to the span data. The added source information can then be displayed along with the query SQL in the Sentry UI. The feature only works with Ruby 3.2+ and Rails 7.1+. * Make the query source location feature toggleable * Only record query source if it takes longer than db_query_source_threshold_ms This avoids the overhead of recording the source in fast queries, which in general don't need to be traced. The threshold is configurable via `config.rails.db_query_source_threshold_ms` and the default is 100ms. * Update changelog --- CHANGELOG.md | 4 + .../lib/sentry/rails/configuration.rb | 10 ++ .../rails/tracing/active_record_subscriber.rb | 97 ++++++++++++++----- .../tracing/active_record_subscriber_spec.rb | 77 +++++++++++++++ sentry-ruby/lib/sentry/span.rb | 5 + 5 files changed, 170 insertions(+), 23 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index f5d4328d9..547e634e0 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -17,7 +17,11 @@ config.enabled_patches += [:graphql] end ``` + - Add `Sentry.get_trace_propagation_meta` helper for injecting meta tags into views ([#2314](https://github.com/getsentry/sentry-ruby/pull/2314)) +- Add query source support to `sentry-rails` ([#2313](https://github.com/getsentry/sentry-ruby/pull/2313)) + + The feature is only activated in apps that use Ruby 3.2+ and Rails 7.1+. By default only queries that take longer than 100ms will have source recorded, which can be adjusted by updating the value of `config.rails.db_query_source_threshold_ms`. ### Bug Fixes diff --git a/sentry-rails/lib/sentry/rails/configuration.rb b/sentry-rails/lib/sentry/rails/configuration.rb index ce385408c..883700142 100644 --- a/sentry-rails/lib/sentry/rails/configuration.rb +++ b/sentry-rails/lib/sentry/rails/configuration.rb @@ -126,6 +126,14 @@ class Configuration attr_accessor :tracing_subscribers + # When the ActiveRecordSubscriber is enabled, capture the source location of the query in the span data. + # This is enabled by default, but can be disabled by setting this to false. + attr_accessor :enable_db_query_source + + # The threshold in milliseconds for the ActiveRecordSubscriber to capture the source location of the query + # in the span data. Default is 100ms. + attr_accessor :db_query_source_threshold_ms + # sentry-rails by default skips asset request' transactions by checking if the path matches # # ```rb @@ -157,6 +165,8 @@ def initialize Sentry::Rails::Tracing::ActiveRecordSubscriber, Sentry::Rails::Tracing::ActiveStorageSubscriber ]) + @enable_db_query_source = true + @db_query_source_threshold_ms = 100 @active_support_logger_subscription_items = Sentry::Rails::ACTIVE_SUPPORT_LOGGER_SUBSCRIPTION_ITEMS_DEFAULT.dup end end diff --git a/sentry-rails/lib/sentry/rails/tracing/active_record_subscriber.rb b/sentry-rails/lib/sentry/rails/tracing/active_record_subscriber.rb index ab25273a9..113ebba76 100644 --- a/sentry-rails/lib/sentry/rails/tracing/active_record_subscriber.rb +++ b/sentry-rails/lib/sentry/rails/tracing/active_record_subscriber.rb @@ -8,38 +8,89 @@ class ActiveRecordSubscriber < AbstractSubscriber SPAN_PREFIX = "db.".freeze EXCLUDED_EVENTS = ["SCHEMA", "TRANSACTION"].freeze - def self.subscribe! - subscribe_to_event(EVENT_NAMES) do |event_name, duration, payload| - next if EXCLUDED_EVENTS.include? payload[:name] + SUPPORT_SOURCE_LOCATION = ActiveSupport::BacktraceCleaner.method_defined?(:clean_frame) - record_on_current_span(op: SPAN_PREFIX + event_name, start_timestamp: payload[START_TIMESTAMP_NAME], description: payload[:sql], duration: duration) do |span| - span.set_tag(:cached, true) if payload.fetch(:cached, false) # cached key is only set for hits in the QueryCache, from Rails 5.1 + if SUPPORT_SOURCE_LOCATION + # Need to be specific down to the lib path so queries generated in specs don't get ignored + SENTRY_RUBY_PATH = File.join(Gem::Specification.find_by_name("sentry-ruby").full_gem_path, "lib") + SENTRY_RAILS_PATH = File.join(Gem::Specification.find_by_name("sentry-rails").full_gem_path, "lib") - connection = payload[:connection] + class_attribute :backtrace_cleaner, default: (ActiveSupport::BacktraceCleaner.new.tap do |cleaner| + cleaner.add_silencer { |line| line.include?(SENTRY_RUBY_PATH) || line.include?(SENTRY_RAILS_PATH) } + end) + end - if payload[:connection_id] - span.set_data(:connection_id, payload[:connection_id]) + class << self + def subscribe! + record_query_source = SUPPORT_SOURCE_LOCATION && Sentry.configuration.rails.enable_db_query_source + query_source_threshold = Sentry.configuration.rails.db_query_source_threshold_ms - # we fallback to the base connection on rails < 6.0.0 since the payload doesn't have it - connection ||= ActiveRecord::Base.connection_pool.connections.find { |conn| conn.object_id == payload[:connection_id] } - end + subscribe_to_event(EVENT_NAMES) do |event_name, duration, payload| + next if EXCLUDED_EVENTS.include? payload[:name] + + record_on_current_span(op: SPAN_PREFIX + event_name, start_timestamp: payload[START_TIMESTAMP_NAME], description: payload[:sql], duration: duration) do |span| + span.set_tag(:cached, true) if payload.fetch(:cached, false) # cached key is only set for hits in the QueryCache, from Rails 5.1 - next unless connection + connection = payload[:connection] - db_config = - if connection.pool.respond_to?(:db_config) - connection.pool.db_config.configuration_hash - elsif connection.pool.respond_to?(:spec) - connection.pool.spec.config + if payload[:connection_id] + span.set_data(:connection_id, payload[:connection_id]) + + # we fallback to the base connection on rails < 6.0.0 since the payload doesn't have it + connection ||= ActiveRecord::Base.connection_pool.connections.find { |conn| conn.object_id == payload[:connection_id] } end - next unless db_config + next unless connection + + db_config = + if connection.pool.respond_to?(:db_config) + connection.pool.db_config.configuration_hash + elsif connection.pool.respond_to?(:spec) + connection.pool.spec.config + end + + next unless db_config + + span.set_data(Span::DataConventions::DB_SYSTEM, db_config[:adapter]) if db_config[:adapter] + span.set_data(Span::DataConventions::DB_NAME, db_config[:database]) if db_config[:database] + span.set_data(Span::DataConventions::SERVER_ADDRESS, db_config[:host]) if db_config[:host] + span.set_data(Span::DataConventions::SERVER_PORT, db_config[:port]) if db_config[:port] + span.set_data(Span::DataConventions::SERVER_SOCKET_ADDRESS, db_config[:socket]) if db_config[:socket] + + next unless record_query_source + + # both duration and query_source_threshold are in ms + next unless duration >= query_source_threshold - span.set_data(Span::DataConventions::DB_SYSTEM, db_config[:adapter]) if db_config[:adapter] - span.set_data(Span::DataConventions::DB_NAME, db_config[:database]) if db_config[:database] - span.set_data(Span::DataConventions::SERVER_ADDRESS, db_config[:host]) if db_config[:host] - span.set_data(Span::DataConventions::SERVER_PORT, db_config[:port]) if db_config[:port] - span.set_data(Span::DataConventions::SERVER_SOCKET_ADDRESS, db_config[:socket]) if db_config[:socket] + source_location = query_source_location + + if source_location + backtrace_line = Sentry::Backtrace::Line.parse(source_location) + span.set_data(Span::DataConventions::FILEPATH, backtrace_line.file) if backtrace_line.file + span.set_data(Span::DataConventions::LINENO, backtrace_line.number) if backtrace_line.number + span.set_data(Span::DataConventions::FUNCTION, backtrace_line.method) if backtrace_line.method + # Only JRuby has namespace in the backtrace + span.set_data(Span::DataConventions::NAMESPACE, backtrace_line.module_name) if backtrace_line.module_name + end + end + end + end + + # Thread.each_caller_location is an API added in Ruby 3.2 that doesn't always collect the entire stack like + # Kernel#caller or #caller_locations do. See https://github.com/rails/rails/pull/49095 for more context. + if SUPPORT_SOURCE_LOCATION && Thread.respond_to?(:each_caller_location) + def query_source_location + Thread.each_caller_location do |location| + frame = backtrace_cleaner.clean_frame(location) + return frame if frame + end + nil + end + else + # Since Sentry is mostly used in production, we don't want to fallback to the slower implementation + # and adds potentially big overhead to the application. + def query_source_location + nil end end end diff --git a/sentry-rails/spec/sentry/rails/tracing/active_record_subscriber_spec.rb b/sentry-rails/spec/sentry/rails/tracing/active_record_subscriber_spec.rb index 4e385a374..ecdb2ab4b 100644 --- a/sentry-rails/spec/sentry/rails/tracing/active_record_subscriber_spec.rb +++ b/sentry-rails/spec/sentry/rails/tracing/active_record_subscriber_spec.rb @@ -6,10 +6,15 @@ end context "when transaction is sampled" do + let(:enable_db_query_source) { true } + let(:db_query_source_threshold_ms) { 0 } + before do make_basic_app do |config| config.traces_sample_rate = 1.0 config.rails.tracing_subscribers = [described_class] + config.rails.enable_db_query_source = enable_db_query_source + config.rails.db_query_source_threshold_ms = db_query_source_threshold_ms end end @@ -38,6 +43,78 @@ expect(data["db.system"]).to eq("sqlite3") end + context "when query source location is avaialble", skip: RUBY_VERSION.to_f < 3.2 || Rails.version.to_f < 7.1 do + def foo + Post.all.to_a + end + query_line = __LINE__ - 2 + + before do + transaction = Sentry::Transaction.new(sampled: true, hub: Sentry.get_current_hub) + Sentry.get_current_scope.set_span(transaction) + + foo + + transaction.finish + end + + context "when config.rails.enable_db_query_source is false" do + let(:enable_db_query_source) { false } + + it "doesn't record query's source location" do + expect(transport.events.count).to eq(1) + + transaction = transport.events.first.to_hash + expect(transaction[:type]).to eq("transaction") + expect(transaction[:spans].count).to eq(1) + + span = transaction[:spans][0] + data = span[:data] + expect(data["db.name"]).to include("db") + expect(data["code.filepath"]).to eq(nil) + expect(data["code.lineno"]).to eq(nil) + expect(data["code.function"]).to eq(nil) + end + end + + context "when the query takes longer than the threshold" do + let(:db_query_source_threshold_ms) { 0 } + + it "records query's source location" do + expect(transport.events.count).to eq(1) + + transaction = transport.events.first.to_hash + expect(transaction[:type]).to eq("transaction") + expect(transaction[:spans].count).to eq(1) + + span = transaction[:spans][0] + data = span[:data] + expect(data["code.filepath"]).to eq(__FILE__) + expect(data["code.lineno"]).to eq(query_line) + expect(data["code.function"]).to eq("foo") + end + end + + context "when the query takes shorter than the threshold" do + let(:db_query_source_threshold_ms) { 1000 } + + it "doesn't record query's source location" do + expect(transport.events.count).to eq(1) + + transaction = transport.events.first.to_hash + expect(transaction[:type]).to eq("transaction") + expect(transaction[:spans].count).to eq(1) + + span = transaction[:spans][0] + data = span[:data] + expect(data["db.name"]).to include("db") + expect(data["code.filepath"]).to eq(nil) + expect(data["code.lineno"]).to eq(nil) + expect(data["code.function"]).to eq(nil) + end + end + end + it "records database cached query events", skip: Rails.version.to_f < 5.1 do transaction = Sentry::Transaction.new(sampled: true, hub: Sentry.get_current_hub) Sentry.get_current_scope.set_span(transaction) diff --git a/sentry-ruby/lib/sentry/span.rb b/sentry-ruby/lib/sentry/span.rb index 69374b496..d3b0a336d 100644 --- a/sentry-ruby/lib/sentry/span.rb +++ b/sentry-ruby/lib/sentry/span.rb @@ -39,6 +39,11 @@ module DataConventions # Recommended: If different than server.port. # Example: 16456 SERVER_SOCKET_PORT = "server.socket.port" + + FILEPATH = "code.filepath" + LINENO = "code.lineno" + FUNCTION = "code.function" + NAMESPACE = "code.namespace" end STATUS_MAP = {