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

@@ -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
 

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

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

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)

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 = {